Random error handling local file creation detected by Watchdog

02:32:43 [INFO]      [exec] ======================================================================
02:32:43 [INFO]      [exec] FAIL: test_content_with_accents_from_client (nxdrive.tests.test_integration_encoding.TestIntegrationEncoding)
02:32:43 [INFO]      [exec] ----------------------------------------------------------------------
02:32:43 [INFO]      [exec] Traceback (most recent call last):
02:32:43 [INFO]      [exec]   File "/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive/tests/test_integration_encoding.py", line 90, in test_content_with_accents_from_client
02:32:43 [INFO]      [exec]     self._synchronize_and_assert(1)
02:32:43 [INFO]      [exec]   File "/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive/tests/test_integration_encoding.py", line 106, in _synchronize_and_assert
02:32:43 [INFO]      [exec]     self.assertEqual(n_synchronized, expected_synchronized)
02:32:43 [INFO]      [exec] AssertionError: 0 != 1
02:32:43 [INFO]      [exec] -------------------- >> begin captured logging << --------------------
02:32:43 [INFO]      [exec] nxdrive.controller: INFO: nxdrive installed in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive'
02:32:43 [INFO]      [exec] nxdrive.controller: INFO: nxdrive configured in '/private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/nuxeo-drive-conf'
02:32:43 [INFO]      [exec] alembic.migration: INFO: Context impl SQLiteImpl.
02:32:43 [INFO]      [exec] alembic.migration: INFO: Will assume non-transactional DDL.
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed.
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision.
02:32:43 [INFO]      [exec] nxdrive.model: DEBUG: Set client version to 1.3-dev
02:32:43 [INFO]      [exec] nxdrive.controller: INFO: nxdrive installed in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive'
02:32:43 [INFO]      [exec] nxdrive.controller: INFO: nxdrive configured in '/private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpwMYkfr-nxdrive-tests-user-2/nuxeo-drive-conf'
02:32:43 [INFO]      [exec] alembic.migration: INFO: Context impl SQLiteImpl.
02:32:43 [INFO]      [exec] alembic.migration: INFO: Will assume non-transactional DDL.
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed.
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6
02:32:43 [INFO]      [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision.
02:32:43 [INFO]      [exec] nxdrive.model: DEBUG: Set client version to 1.3-dev
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-administrator-device', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'} and cookies []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"value": "/"}}'
02:32:43 [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":"768ef68b-7640-48dc-a3e2-6fc23c39c6c5","path":"/","type":"Root","state":null,"versionLabel":"","isCheckedOut":true,"title":"768ef68b-7640-48dc-a3e2-6fc23c39c6c5","properties":{"dc:creator":null,"dc:source":null,"dc:contributors":[],"dc:nature":null,"dc:created":null,"dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":null,"dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":null,"dc:lastContributor":null,"common:icon":null,"common:icon-expanded":null,"common:size":null},"facets":["Folderish","NotCollectionMember"],"changeToken":null,"contextParameters":{}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"userNames": "user_1, user_2", "permission": "ReadWrite"}}'
02:32:43 [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'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"value": "/default-domain/workspaces/nuxeo-drive-test-workspace"}}'
02:32:43 [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":"2735bd3c-8003-4b8d-91d1-bd6194ee5b43","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-10T00:19:44.37Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-09-10T00:19:44.37Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-10T00:19:44.37Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:useCaptcha":null,"webc:welcomeText":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1410308384376","contextParameters":{}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjYjNiZmY='} and cookies []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'2735bd3c-8003-4b8d-91d1-bd6194ee5b43'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjYjNiZmY='}, cookies [] and JSON payload '{"params": {"value": "2735bd3c-8003-4b8d-91d1-bd6194ee5b43"}}'
02:32:43 [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":"2735bd3c-8003-4b8d-91d1-bd6194ee5b43","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-10T00:19:44.37Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-09-10T00:19:44.37Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-10T00:19:44.37Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:useCaptcha":null,"webc:welcomeText":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1410308384376","contextParameters":{}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjoyNzYxNmQ='} and cookies []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'2735bd3c-8003-4b8d-91d1-bd6194ee5b43'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-2', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjoyNzYxNmQ='}, cookies [] and JSON payload '{"params": {"value": "2735bd3c-8003-4b8d-91d1-bd6194ee5b43"}}'
02:32:43 [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":"2735bd3c-8003-4b8d-91d1-bd6194ee5b43","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-10T00:19:44.37Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-09-10T00:19:44.37Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-10T00:19:44.37Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:useCaptcha":null,"webc:welcomeText":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1410308384376","contextParameters":{}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjYjNiZmY='} and cookies []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjoyNzYxNmQ='} and cookies []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjYjNiZmY='} and cookies []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Mac+OSX+Desktop&revoke=false&deviceId=2a207f5e388011e4a2e9002500d3a152&permission=ReadWrite with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjYjNiZmY='} and cookies []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Got token 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a' with cookies []
02:32:43 [INFO]      [exec] nxdrive.controller: INFO: Binding '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive' to 'http://localhost:8080/nuxeo/' with account 'nuxeoDriveTestUser_user_1'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'} and cookies []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {}}'
02:32:43 [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#","creationDate":816,"folder":true,"parentId":null,"canDelete":false,"creator":"system","canRename":false,"lastModificationDate":816,"userName":"nuxeoDriveTestUser_user_1"}'
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '1970-01-01 01:00:00'
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 1970-01-01 01:00:00 and updated last_sync_date to 2014-09-10 02:19:44.823389
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"5.9.6-SNAPSHOT","updateSiteURL":"http://community.nuxeo.com/static/drive/"}'
02:32:43 [INFO]      [exec] nxdrive.controller: INFO: Fetched update info from server: {u'serverVersion': u'5.9.6-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/'}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'} and cookies []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:2735bd3c-8003-4b8d-91d1-bd6194ee5b43', 'params': {'enable': True}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Authentication-Token': u'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"input": "doc:2735bd3c-8003-4b8d-91d1-bd6194ee5b43", "params": {"enable": true}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
02:32:43 [INFO]      [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=21957)
02:32:43 [INFO]      [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive: []
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":428,"fileSystemChanges":[],"syncDate":1410308385000,"activeSynchronizationRootDefinitions":"default:2735bd3c-8003-4b8d-91d1-bd6194ee5b43","hasTooManyChanges":false}'
02:32:43 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote full scan of /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive. Reasons: forced: False, too many changes: False, first pass: True
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
02:32:43 [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#","creationDate":30,"folder":true,"parentId":null,"canDelete":false,"creator":"system","canRename":false,"lastModificationDate":30,"userName":"nuxeoDriveTestUser_user_1"}'
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '1970-01-01 01:00:00', '1970-01-01 01:00:00'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43","creationDate":1410308384376,"folder":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canDelete":true,"creator":"Administrator","canRename":true,"lastModificationDate":1410308384924,"userName":"nuxeoDriveTestUser_user_1"}]'
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-10 02:19:44'
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-10 02:19:44 and updated last_sync_date to 2014-09-10 02:19:45.071721
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-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'>
02:32:43 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-10 02:19:44', '2014-09-10 02:19:44'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43"}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
02:32:43 [INFO]      [exec] nxdrive.synchronizer: INFO: Watching FS modification on : /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43"}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43","creationDate":1410308384376,"folder":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canDelete":true,"creator":"Administrator","canRename":true,"lastModificationDate":1410308384924,"userName":"nuxeoDriveTestUser_user_1"}'
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-10 02:19:44', '2014-09-10 02:19:44'
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-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'>
02:32:43 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive/'
02:32:43 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Nuxeo Drive Test Workspace
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-10 02:19:44', '2014-09-10 02:19:44'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#2735bd3c-8003-4b8d-91d1-bd6194ee5b43"}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
02:32:43 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-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'>
02:32:43 [INFO]      [exec] nxdrive.controller: INFO: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive: []
02:32:43 [INFO]      [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.026s, remote: 0.132s sync: 0.099s
02:32:43 [INFO]      [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops
02:32:43 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session
02:32:43 [INFO]      [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x113d01950>, ending any transaction in progress and releasing underlying connections from the pool
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {}}'
02:32:43 [INFO]      [exec] nxdrive.synchronizer: TRACE: 1 <DirModifiedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive'>
02:32:43 [INFO]      [exec] nxdrive.synchronizer: TRACE: 2 <DirCreatedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
02:32:43 [INFO]      [exec] nxdrive.synchronizer: TRACE: 3 <FileCreatedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Nom sans accents'>
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 428, 'lastSyncActiveRootDefinitions': u'default:2735bd3c-8003-4b8d-91d1-bd6194ee5b43'}}
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'd83e1a38-2b89-4868-ab1e-2b08fce3c78a', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'2a207f5e388011e4a2e9002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 428, "lastSyncActiveRootDefinitions": "default:2735bd3c-8003-4b8d-91d1-bd6194ee5b43"}}'
02:32:43 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":434,"fileSystemChanges":[],"syncDate":1410308385000,"activeSynchronizationRootDefinitions":"default:2735bd3c-8003-4b8d-91d1-bd6194ee5b43","hasTooManyChanges":false}'
02:32:43 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Sorted events: [<DirModifiedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive'>, <DirCreatedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>, <FileCreatedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Nom sans accents'>]
02:32:43 [INFO]      [exec] nxdrive.synchronizer: INFO: <type 'exceptions.TypeError'>
02:32:43 [INFO]      [exec] nxdrive.synchronizer: INFO: <type 'exceptions.TypeError'>
02:32:43 [INFO]      [exec] nxdrive.synchronizer: INFO: <type 'exceptions.TypeError'>
02:32:43 [INFO]      [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp2zST1G-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 0, pending: 0, local: 3.009s, remote: 0.028s sync: 0.016s
02:32:43 [INFO]      [exec] --------------------- >> end captured logging << ---------------------