See http://qa.nuxeo.org/jenkins/view/Drive/job/FT-nuxeo-drive-1.4-windows/565/consoleFull
15:29:52 [INFO] [exec] ====================================================================== 15:29:52 [INFO] [exec] FAIL: test_drive_edit_remote_move_non_sync_root_to_sync_root (nxdrive.tests.test_drive_edit.TestDriveEdit) 15:29:52 [INFO] [exec] ---------------------------------------------------------------------- 15:29:52 [INFO] [exec] Traceback (most recent call last): 15:29:52 [INFO] [exec] File "c:\hudson\workspace\FT-nuxeo-drive-1.4-windows\nuxeo-drive-client\nxdrive\tests\test_drive_edit.py", line 231, in test_drive_edit_remote_move_non_sync_root_to_sync_root 15:29:52 [INFO] [exec] self.assertTrue(local.exists('/syncRoot/test.odt')) 15:29:52 [INFO] [exec] AssertionError: False is not true 15:29:52 [INFO] [exec] -------------------- >> begin captured logging << -------------------- 15:29:52 [INFO] [exec] nxdrive.controller: INFO: nxdrive installed in 'c:\hudson\workspace\FT-nuxeo-drive-1.4-windows\ftest\target\nxdrive_msi\SourceDir\appdata\nuxeo-drive-1.4.0106.win32\library.zip\nxdrive' 15:29:52 [INFO] [exec] nxdrive.controller: INFO: nxdrive configured in 'c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\nuxeo-drive-conf' 15:29:52 [INFO] [exec] alembic.migration: INFO: Context impl SQLiteImpl. 15:29:52 [INFO] [exec] alembic.migration: INFO: Will assume non-transactional DDL. 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed. 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: Head Alembic revision: 10eaff28d372 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 10eaff28d372 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: Current Alembic revision: 10eaff28d372 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision. 15:29:52 [INFO] [exec] nxdrive.model: DEBUG: Set client version to 1.4.0106 15:29:52 [INFO] [exec] nxdrive.controller: INFO: nxdrive installed in 'c:\hudson\workspace\FT-nuxeo-drive-1.4-windows\ftest\target\nxdrive_msi\SourceDir\appdata\nuxeo-drive-1.4.0106.win32\library.zip\nxdrive' 15:29:52 [INFO] [exec] nxdrive.controller: INFO: nxdrive configured in 'c:\users\nuxeo\appdata\local\temp\tmpjvo9ig-nxdrive-tests-user-2\nuxeo-drive-conf' 15:29:52 [INFO] [exec] alembic.migration: INFO: Context impl SQLiteImpl. 15:29:52 [INFO] [exec] alembic.migration: INFO: Will assume non-transactional DDL. 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed. 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: Head Alembic revision: 10eaff28d372 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 10eaff28d372 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: Current Alembic revision: 10eaff28d372 15:29:52 [INFO] [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision. 15:29:52 [INFO] [exec] nxdrive.model: DEBUG: Set client version to 1.4.0106 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.4.0106', 'X-Device-Id': u'nxdrive-test-administrator-device', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'} and cookies [] 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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": "/"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"56a23619-ea47-4b39-80d4-4bb972853756","path":"/","type":"Root","state":null,"parentRef":"/","versionLabel":"","isCheckedOut":true,"title":"56a23619-ea47-4b39-80d4-4bb972853756","properties":{"dc:creator":null,"dc:source":null,"dc:nature":null,"dc:contributors":[],"dc:created":null,"dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":null,"dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":null,"dc:lastContributor":null,"common:icon":null,"common:icon-expanded":null,"common:size":null},"facets":["Folderish","NotCollectionMember"],"changeToken":null,"contextParameters":{}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests' with cookies [] has content-type 'text/plain' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"f5c0485a-1168-465e-b7c1-08492b5eb7cd","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"4c1829ec-8a07-4519-a157-62f93238f9a6","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2015-01-06T14:22:42.65Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:nature":null,"dc:contributors":["Administrator"],"dc:created":"2015-01-06T14:22:42.65Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2015-01-06T14:22:42.65Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:welcomeText":null,"webc:useCaptcha":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1420554162654","contextParameters":{}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.4.0106', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='} and cookies [] 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'f5c0485a-1168-465e-b7c1-08492b5eb7cd'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='}, cookies [] and JSON payload '{"params": {"value": "f5c0485a-1168-465e-b7c1-08492b5eb7cd"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"f5c0485a-1168-465e-b7c1-08492b5eb7cd","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"4c1829ec-8a07-4519-a157-62f93238f9a6","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2015-01-06T14:22:42.65Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:nature":null,"dc:contributors":["Administrator"],"dc:created":"2015-01-06T14:22:42.65Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2015-01-06T14:22:42.65Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:welcomeText":null,"webc:useCaptcha":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1420554162654","contextParameters":{}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.4.0106', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjozYjY4MmM='} and cookies [] 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'f5c0485a-1168-465e-b7c1-08492b5eb7cd'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-2', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjozYjY4MmM='}, cookies [] and JSON payload '{"params": {"value": "f5c0485a-1168-465e-b7c1-08492b5eb7cd"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"f5c0485a-1168-465e-b7c1-08492b5eb7cd","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"4c1829ec-8a07-4519-a157-62f93238f9a6","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2015-01-06T14:22:42.65Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:nature":null,"dc:contributors":["Administrator"],"dc:created":"2015-01-06T14:22:42.65Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2015-01-06T14:22:42.65Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:welcomeText":null,"webc:useCaptcha":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1420554162654","contextParameters":{}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.4.0106', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='} and cookies [] 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.4.0106', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjozYjY4MmM='} and cookies [] 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.4.0106', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='} and cookies [] 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Windows+Desktop&revoke=false&deviceId=79e4f12195af11e4a6500024e814f531&permission=ReadWrite with headers {'X-Client-Version': '1.4.0106', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='} and cookies [] 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Got token '297eb274-9768-4330-af9b-a6830d6217ef' with cookies [] 15:29:52 [INFO] [exec] nxdrive.controller: INFO: Binding 'c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive' to 'http://localhost:8080/nuxeo/' with account 'nuxeoDriveTestUser_user_1' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.4.0106'} and cookies [] 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creator":"system","folder":true,"creationDate":982,"lastModificationDate":982,"parentId":null,"canRename":false,"canDelete":false,"lastContributor":"system","userName":"nuxeoDriveTestUser_user_1"}' 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'> 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'> 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"7.1-SNAPSHOT","updateSiteURL":"http://community.nuxeo.com/static/drive/"}' 15:29:52 [INFO] [exec] nxdrive.controller: INFO: Fetched update info from server: {u'serverVersion': u'7.1-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/'} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/', 'params': {'type': 'File', 'name': 'test.odt', 'properties': 'dc:title=test.odt'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/", "params": {"type": "File", "name": "test.odt", "properties": "dc:title=test.odt"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"9088b2db-c94a-4006-aa08-725346d59690","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/test.odt","type":"File","state":"project","parentRef":"f5c0485a-1168-465e-b7c1-08492b5eb7cd","versionLabel":"0.0","isCheckedOut":true,"title":"test.odt","lastModified":"2015-01-06T14:22:43.01Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2015-01-06T14:22:43.01Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2015-01-06T14:22:43.01Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"test.odt","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"common:icon":"/icons/file.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"relatedtext:relatedtextresources":[]},"facets":["Downloadable","Commentable","Versionable","Publishable","HasRelatedText"],"changeToken":"1420554163013","contextParameters":{}}' 15:29:52 [INFO] [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'test.odt' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 13L, 'X-Client-Version': '1.4.0106', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 13L, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1420554163.03_679612090', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'test.odt'} and cookies [] for file c:\users\nuxeo\appdata\local\temp\tmpdf_rxg-nxdrive-uploads\tmpv1rhly-nxdrive-file-to-upload 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1420554163.03_679612090"}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of Blob.Attach with file c:\users\nuxeo\appdata\local\temp\tmpdf_rxg-nxdrive-uploads\tmpv1rhly-nxdrive-file-to-upload 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1420554163.03_679612090', 'document': u'9088b2db-c94a-4006-aa08-725346d59690', 'fileIdx': '0', 'operationId': 'Blob.Attach'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='}, cookies [] and JSON payload '{"params": {"batchId": "1420554163.03_679612090", "document": "9088b2db-c94a-4006-aa08-725346d59690", "fileIdx": "0", "operationId": "Blob.Attach"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies [] has content-type 'application/vnd.oasis.opendocument.text' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'297eb274-9768-4330-af9b-a6830d6217ef', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.4.0106'} and cookies [] 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: Local edition: filename = test.odt, unquoted filename = test.odt, quoted filename = test.odt 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: Downloading file 'test.odt' in '\\?\c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive\Locally Edited' with URL 'http://localhost:8080/nuxeo/nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt' with headers: {'X-Authentication-Token': u'297eb274-9768-4330-af9b-a6830d6217ef', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.4.0106'} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:9088b2db-c94a-4006-aa08-725346d59690', 'params': {}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.AddToLocallyEditedCollection with headers {'X-Authentication-Token': u'297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"input": "doc:9088b2db-c94a-4006-aa08-725346d59690", "params": {}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.AddToLocallyEditedCollection' with cookies []: '{"entity-type":"document","repository":"default","uid":"9088b2db-c94a-4006-aa08-725346d59690","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/test.odt","type":"File","state":"project","parentRef":"f5c0485a-1168-465e-b7c1-08492b5eb7cd","versionLabel":"0.0","isCheckedOut":true,"title":"test.odt","lastModified":"2015-01-06T14:22:43.04Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2015-01-06T14:22:43.01Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2015-01-06T14:22:43.04Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"test.odt","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"thumb:thumbnail":{"name":"a296249f9b03952cc068c6c64965d9b5","mime-type":"application/octet-stream","encoding":null,"digest":"a296249f9b03952cc068c6c64965d9b5","length":"448","data":"http://localhost:8080/nuxeo/nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/thumbnail:thumb:thumbnail/a296249f9b03952cc068c6c64965d9b5"},"common:icon":"/icons/odt.png","common:icon-expanded":null,"common:size":13,"file:content":{"name":"test.odt","mime-type":"application/vnd.oasis.opendocument.text","encoding":null,"digest":"b8ab309a6b9a3f448092a136afa8fa25","length":"13","data":"http://localhost:8080/nuxeo/nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/file:content/test.odt"},"file:filename":null,"collectionMember:collectionIds":[],"relatedtext:relatedtextresources":[]},"facets":["Downloadable","Commentable","CollectionMember","Versionable","Publishable","HasRelatedText","Thumbnail"],"changeToken":"1420554163044","contextParameters":{}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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": {}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type '' 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=2308) 15:29:52 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive: [] 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":768,"fileSystemChanges":[],"hasTooManyChanges":false,"syncDate":1420554163000,"activeSynchronizationRootDefinitions":"default:699ca4c2-7032-485c-b636-3d1af1089aa9"}' 15:29:52 [INFO] [exec] nxdrive.client.remote_filtered_file_system_client: TRACE: result['hasTooManyChanges'] = False 15:29:52 [INFO] [exec] nxdrive.client.remote_filtered_file_system_client: TRACE: server_binding.last_filter_date = None 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote full scan of c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive. Reasons: forced: False, too many changes: False, first pass: True 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creator":"system","folder":true,"creationDate":356,"lastModificationDate":356,"parentId":null,"canRename":false,"canDelete":false,"lastContributor":"system","userName":"nuxeoDriveTestUser_user_1"}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":false,"name":"Locally Edited","id":"collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","creator":"nuxeoDriveTestUser_user_1","folder":true,"creationDate":1420554163200,"lastModificationDate":1420554163231,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"}]' 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Locally Edited', local_state=None, remote_state='modified', pair_state='unknown'> 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Locally Edited', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Locally Edited', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0> 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"b8ab309a6b9a3f448092a136afa8fa25","canUpdate":true,"downloadURL":"nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt","digestAlgorithm":"md5","name":"test.odt","id":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9/defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","creator":"nuxeoDriveTestUser_user_1","folder":false,"creationDate":1420554163013,"lastModificationDate":1420554163044,"parentId":"collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"}]' 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state=None, remote_state='modified', pair_state='unknown'> 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0> 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Matched local /Locally Edited with remote Locally Edited by name only 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Locally Edited', local_state='created', remote_state=u'modified', pair_state='conflicted'> 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'test.odt', local_state='created', remote_state=u'modified', pair_state='conflicted'> 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Matched local /Locally Edited/test.odt with remote test.odt with digest 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 2 pending item(s) 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited', remote_name=u'Locally Edited', local_state=u'created', remote_state=u'modified', pair_state=u'conflicted', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state=u'created', remote_state=u'modified', pair_state=u'conflicted', error_count=0>] 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited', remote_name=u'Locally Edited', local_state=u'created', remote_state=u'modified', pair_state=u'conflicted', error_count=0> 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9', 'parentId': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9", "parentId": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"name":"Locally Edited","id":"collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","creator":"nuxeoDriveTestUser_user_1","folder":true,"creationDate":1420554163200,"lastModificationDate":1420554163231,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"}' 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_conflicted of <nxdrive.synchronizer.Synchronizer object at 0x06BB2270>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited', remote_name=u'Locally Edited', local_state=u'created', remote_state=u'modified', pair_state=u'conflicted', error_count=0> 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Automated conflict resolution using name for c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive\Locally Edited 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Locally Edited', remote_name=u'Locally Edited', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'> 15:29:52 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive: [] 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 1 pending item(s) 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state=u'created', remote_state=u'modified', pair_state=u'conflicted', error_count=0>] 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state=u'created', remote_state=u'modified', pair_state=u'conflicted', error_count=0> 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690', 'parentId': u'collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690", "parentId": "collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"b8ab309a6b9a3f448092a136afa8fa25","canUpdate":true,"downloadURL":"nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt","digestAlgorithm":"md5","name":"test.odt","id":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9/defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","creator":"nuxeoDriveTestUser_user_1","folder":false,"creationDate":1420554163013,"lastModificationDate":1420554163044,"parentId":"collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"}' 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_conflicted of <nxdrive.synchronizer.Synchronizer object at 0x06BB2270>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state=u'created', remote_state=u'modified', pair_state=u'conflicted', error_count=0> 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Automated conflict resolution using digest for c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive\Locally Edited\test.odt 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'> 15:29:52 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive: [u'test.odt'] 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: [c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 2, pending: 2, local: 0.047s, remote: 0.124s sync: 0.078s 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x07CB41F0>, ending any transaction in progress and releasing underlying connections from the pool 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: As we are under Windows, dispose connection pool to make sure all connections are closed, avoiding any WindowsError due to a Python process using the database file 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=2308) 15:29:52 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive: [u'test.odt'] 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 768, 'lastSyncActiveRootDefinitions': u'default:699ca4c2-7032-485c-b636-3d1af1089aa9'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"lowerBound": 768, "lastSyncActiveRootDefinitions": "default:699ca4c2-7032-485c-b636-3d1af1089aa9"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":773,"fileSystemChanges":[],"hasTooManyChanges":false,"syncDate":1420554164000,"activeSynchronizationRootDefinitions":"default:699ca4c2-7032-485c-b636-3d1af1089aa9"}' 15:29:52 [INFO] [exec] nxdrive.client.remote_filtered_file_system_client: TRACE: result['hasTooManyChanges'] = False 15:29:52 [INFO] [exec] nxdrive.client.remote_filtered_file_system_client: TRACE: server_binding.last_filter_date = None 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state='modified', remote_state=u'synchronized', pair_state='locally_modified'> 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 1 pending item(s) 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state=u'modified', remote_state=u'synchronized', pair_state=u'locally_modified', error_count=0>] 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state=u'modified', remote_state=u'synchronized', pair_state=u'locally_modified', error_count=0> 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690', 'parentId': u'collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690", "parentId": "collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"b8ab309a6b9a3f448092a136afa8fa25","canUpdate":true,"downloadURL":"nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt","digestAlgorithm":"md5","name":"test.odt","id":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9/defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","creator":"nuxeoDriveTestUser_user_1","folder":false,"creationDate":1420554163013,"lastModificationDate":1420554163044,"parentId":"collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"}' 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_locally_modified of <nxdrive.synchronizer.Synchronizer object at 0x06BB2270>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state=u'modified', remote_state=u'synchronized', pair_state=u'locally_modified', error_count=0> 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Updating remote document 'test.odt'. 15:29:52 [INFO] [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.oasis.opendocument.text' for 'test.odt' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 16L, 'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 16L, 'Cache-Control': 'no-cache', 'X-Batch-Id': '1420554164.63_58075555', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'test.odt', 'X-Client-Version': '1.4.0106'} and cookies [] for file c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive\Locally Edited\test.odt 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1420554164.63_58075555"}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of NuxeoDrive.UpdateFile with file c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive\Locally Edited\test.odt 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1420554164.63_58075555', 'parentId': u'collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9', 'fileIdx': '0', 'id': u'defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690', 'operationId': 'NuxeoDrive.UpdateFile'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'X-Client-Version': '1.4.0106'}, cookies [] and JSON payload '{"params": {"batchId": "1420554164.63_58075555", "parentId": "collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9", "fileIdx": "0", "id": "defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690", "operationId": "NuxeoDrive.UpdateFile"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies []: '{"digest":"0788b34b5d5b3ff7ae0246e1ad99d62b","canUpdate":true,"downloadURL":"nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt","digestAlgorithm":"md5","name":"test.odt","id":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9/defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","creator":"nuxeoDriveTestUser_user_1","folder":false,"creationDate":1420554163013,"lastModificationDate":1420554164651,"parentId":"collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690', 'parentId': u'collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690", "parentId": "collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"0788b34b5d5b3ff7ae0246e1ad99d62b","canUpdate":true,"downloadURL":"nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt","digestAlgorithm":"md5","name":"test.odt","id":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9/defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","creator":"nuxeoDriveTestUser_user_1","folder":false,"creationDate":1420554163013,"lastModificationDate":1420554164651,"parentId":"collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"}' 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Doc test.odt 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' 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state=u'modified', remote_state='modified', pair_state='conflicted'> 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Locally Edited/test.odt', remote_name=u'test.odt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'> 15:29:52 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive: [u'test.odt'] 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: [c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.031s, remote: 0.016s sync: 0.234s 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x07CB41F0>, ending any transaction in progress and releasing underlying connections from the pool 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: As we are under Windows, dispose connection pool to make sure all connections are closed, avoiding any WindowsError due to a Python process using the database file 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/test.odt', 'params': {}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Blob.Get with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/test.odt", "params": {}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Blob.Get' with cookies [] has content-type 'application/vnd.oasis.opendocument.text' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/', 'params': {'type': 'Folder', 'name': 'syncRoot', 'properties': 'dc:title=syncRoot'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/", "params": {"type": "Folder", "name": "syncRoot", "properties": "dc:title=syncRoot"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Create' with cookies []: '{"entity-type":"document","repository":"default","uid":"44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/syncRoot","type":"Folder","state":"project","parentRef":"f5c0485a-1168-465e-b7c1-08492b5eb7cd","versionLabel":"","isCheckedOut":true,"title":"syncRoot","lastModified":"2015-01-06T14:22:44.85Z","properties":{"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2015-01-06T14:22:44.85Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2015-01-06T14:22:44.85Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"syncRoot","dc:lastContributor":"nuxeoDriveTestUser_user_1","common:icon":"/icons/folder.gif","common:icon-expanded":null,"common:size":null},"facets":["Folderish"],"changeToken":"1420554164854","contextParameters":{}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'297eb274-9768-4330-af9b-a6830d6217ef', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.4.0106'} and cookies [] 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:44a7f749-7bdc-4fdc-b897-7dd41ae2e12b', 'params': {'enable': True}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Authentication-Token': u'297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"input": "doc:44a7f749-7bdc-4fdc-b897-7dd41ae2e12b", "params": {"enable": true}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type '' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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": {}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type '' 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=2308) 15:29:52 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive: [u'test.odt'] 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 773, 'lastSyncActiveRootDefinitions': u'default:699ca4c2-7032-485c-b636-3d1af1089aa9'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"lowerBound": 773, "lastSyncActiveRootDefinitions": "default:699ca4c2-7032-485c-b636-3d1af1089aa9"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":787,"fileSystemChanges":[{"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"syncRoot","id":"defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","creator":"nuxeoDriveTestUser_user_1","folder":true,"creationDate":1420554164854,"lastModificationDate":1420554164916,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","eventId":"rootRegistered","fileSystemItemName":"syncRoot","eventDate":1420554164916,"docUuid":"44a7f749-7bdc-4fdc-b897-7dd41ae2e12b"},{"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"syncRoot","id":"defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","creator":"nuxeoDriveTestUser_user_1","folder":true,"creationDate":1420554164854,"lastModificationDate":1420554164916,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","eventId":"documentCreated","fileSystemItemName":"syncRoot","eventDate":1420554164854,"docUuid":"44a7f749-7bdc-4fdc-b897-7dd41ae2e12b"},{"repositoryId":"default","fileSystemItem":{"digest":"0788b34b5d5b3ff7ae0246e1ad99d62b","canUpdate":true,"downloadURL":"nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt","digestAlgorithm":"md5","name":"test.odt","id":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9/defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","creator":"nuxeoDriveTestUser_user_1","folder":false,"creationDate":1420554163013,"lastModificationDate":1420554164651,"parentId":"collectionSyncRootFolderItemFactory#default#699ca4c2-7032-485c-b636-3d1af1089aa9","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","eventId":"documentModified","fileSystemItemName":"test.odt","eventDate":1420554164651,"docUuid":"9088b2db-c94a-4006-aa08-725346d59690"}],"hasTooManyChanges":false,"syncDate":1420554165000,"activeSynchronizationRootDefinitions":"default:699ca4c2-7032-485c-b636-3d1af1089aa9,default:44a7f749-7bdc-4fdc-b897-7dd41ae2e12b"}' 15:29:52 [INFO] [exec] nxdrive.client.remote_filtered_file_system_client: TRACE: result['hasTooManyChanges'] = False 15:29:52 [INFO] [exec] nxdrive.client.remote_filtered_file_system_client: TRACE: server_binding.last_filter_date = None 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: 3 remote changes detected on http://localhost:8080/nuxeo/ 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'syncRoot', local_state=None, remote_state='modified', pair_state='unknown'> 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'syncRoot', local_state='unknown', remote_state='modified', pair_state='remotely_modified'> 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'syncRoot', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0> 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Marked doc_pair 'syncRoot' as remote creation 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of syncRoot 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]' 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Refreshing remote state info for doc_pair '/Locally Edited/test.odt' 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Found 1 pending item(s) 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'syncRoot', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>] 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'syncRoot', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0> 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b', 'parentId': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b", "parentId": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"syncRoot","id":"defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","creator":"nuxeoDriveTestUser_user_1","folder":true,"creationDate":1420554164854,"lastModificationDate":1420554164916,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"}' 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'syncRoot', local_state=u'unknown', remote_state='created', pair_state='remotely_created'> 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x06BB2270>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'syncRoot', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0> 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'syncRoot' in 'c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive\' 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of syncRoot 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]' 15:29:52 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmpfgcnud-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/syncRoot', remote_name=u'syncRoot', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'> 15:29:52 [INFO] [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive: [u'test.odt'] 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: [c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.015s, remote: 0.156s sync: 0.078s 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x07CB41F0>, ending any transaction in progress and releasing underlying connections from the pool 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: As we are under Windows, dispose connection pool to make sure all connections are closed, avoiding any WindowsError due to a Python process using the database file 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/test.odt', 'params': {'target': u'/default-domain/workspaces/nuxeo-drive-test-workspace/syncRoot'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Move with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpmMzMzNGY='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/test.odt", "params": {"target": "/default-domain/workspaces/nuxeo-drive-test-workspace/syncRoot"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Move' with cookies []: '{"entity-type":"document","repository":"default","uid":"9088b2db-c94a-4006-aa08-725346d59690","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/syncRoot/test.odt","type":"File","state":"project","parentRef":"44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","versionLabel":"0.0","isCheckedOut":true,"title":"test.odt","lastModified":"2015-01-06T14:22:44.65Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:nature":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:created":"2015-01-06T14:22:43.01Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2015-01-06T14:22:44.65Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"test.odt","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"thumb:thumbnail":{"name":"4a74ca85fe1d08438ec88c44f5d6c12a","mime-type":"application/octet-stream","encoding":null,"digest":"4a74ca85fe1d08438ec88c44f5d6c12a","length":"518","data":"http://localhost:8080/nuxeo/nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/thumbnail:thumb:thumbnail/4a74ca85fe1d08438ec88c44f5d6c12a"},"common:icon":"/icons/odt.png","common:icon-expanded":null,"common:size":16,"file:content":{"name":"test.odt","mime-type":"application/vnd.oasis.opendocument.text","encoding":null,"digest":"0788b34b5d5b3ff7ae0246e1ad99d62b","length":"16","data":"http://localhost:8080/nuxeo/nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/file:content/test.odt"},"file:filename":"test.odt","collectionMember:collectionIds":["699ca4c2-7032-485c-b636-3d1af1089aa9"],"relatedtext:relatedtextresources":[]},"facets":["Downloadable","Commentable","CollectionMember","Versionable","Publishable","HasRelatedText","Thumbnail"],"changeToken":"1420554164651","contextParameters":{}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion with headers {'X-Client-Version': '1.4.0106', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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": {}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type '' 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=2308) 15:29:52 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive: [u'test.odt'] 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 787, 'lastSyncActiveRootDefinitions': u'default:699ca4c2-7032-485c-b636-3d1af1089aa9,default:44a7f749-7bdc-4fdc-b897-7dd41ae2e12b'}} 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '297eb274-9768-4330-af9b-a6830d6217ef', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'79e4f12195af11e4a6500024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.4.0106', '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.4.0106'}, cookies [] and JSON payload '{"params": {"lowerBound": 787, "lastSyncActiveRootDefinitions": "default:699ca4c2-7032-485c-b636-3d1af1089aa9,default:44a7f749-7bdc-4fdc-b897-7dd41ae2e12b"}}' 15:29:52 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":796,"fileSystemChanges":[{"repositoryId":"default","fileSystemItem":{"digest":"0788b34b5d5b3ff7ae0246e1ad99d62b","canUpdate":true,"downloadURL":"nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt","digestAlgorithm":"md5","name":"test.odt","id":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b/defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","creator":"nuxeoDriveTestUser_user_1","folder":false,"creationDate":1420554163013,"lastModificationDate":1420554164651,"parentId":"defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","eventId":"deleted","fileSystemItemName":"test.odt","eventDate":1420554165306,"docUuid":"9088b2db-c94a-4006-aa08-725346d59690"},{"repositoryId":"default","fileSystemItem":{"digest":"0788b34b5d5b3ff7ae0246e1ad99d62b","canUpdate":true,"downloadURL":"nxbigfile/default/9088b2db-c94a-4006-aa08-725346d59690/blobholder:0/test.odt","digestAlgorithm":"md5","name":"test.odt","id":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b/defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","creator":"nuxeoDriveTestUser_user_1","folder":false,"creationDate":1420554163013,"lastModificationDate":1420554164651,"parentId":"defaultSyncRootFolderItemFactory#default#44a7f749-7bdc-4fdc-b897-7dd41ae2e12b","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#9088b2db-c94a-4006-aa08-725346d59690","eventId":"documentMoved","fileSystemItemName":"test.odt","eventDate":1420554165306,"docUuid":"9088b2db-c94a-4006-aa08-725346d59690"}],"hasTooManyChanges":false,"syncDate":1420554165000,"activeSynchronizationRootDefinitions":"default:699ca4c2-7032-485c-b636-3d1af1089aa9,default:44a7f749-7bdc-4fdc-b897-7dd41ae2e12b"}' 15:29:52 [INFO] [exec] nxdrive.client.remote_filtered_file_system_client: TRACE: result['hasTooManyChanges'] = False 15:29:52 [INFO] [exec] nxdrive.client.remote_filtered_file_system_client: TRACE: server_binding.last_filter_date = None 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Updating remote states 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: 2 remote changes detected on http://localhost:8080/nuxeo/ 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Refreshing remote state info for doc_pair '/Locally Edited/test.odt' 15:29:52 [INFO] [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: [c:\users\nuxeo\appdata\local\temp\tmpfgcnud-nxdrive-tests-user-1\Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 0, pending: 0, local: 0.031s, remote: 0.078s sync: 0.000s 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops 15:29:52 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x07CB41F0>, ending any transaction in progress and releasing underlying connections from the pool 15:29:52 [INFO] [exec] nxdrive.controller: DEBUG: As we are under Windows, dispose connection pool to make sure all connections are closed, avoiding any WindowsError due to a Python process using the database file 15:29:52 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread 15:29:52 [INFO] [exec] --------------------- >> end captured logging << ---------------------
- depends on
-
NXDRIVE-181 Random failure at ine 278, in test_drive_edit_remote_move_sync_root_to_non_sync_root
-
- Resolved
-
- is required by
-
NXDRIVE-170 Refactor functional test framework to run the ndrive program instead of relying on its implementation
-
- Resolved
-
