With:
20:40:34 [INFO] [exec] ======================================================================
20:40:34 [INFO] [exec] FAIL: Test update/deletion of a locally locked file.
20:40:34 [INFO] [exec] ----------------------------------------------------------------------
20:40:34 [INFO] [exec] Traceback (most recent call last):
20:40:34 [INFO] [exec] File "/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive/tests/test_integration_windows.py", line 154, in test_concurrent_file_access
20:40:34 [INFO] [exec] 'Updated content.')
20:40:34 [INFO] [exec] AssertionError: 'Some content to update.' != 'Updated content.'
20:40:34 [INFO] [exec] -------------------- >> begin captured logging << --------------------
20:40:34 [INFO] [exec] nxdrive.controller: INFO: nxdrive installed in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive'
20:40:34 [INFO] [exec] nxdrive.controller: INFO: nxdrive configured in '/private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/nuxeo-drive-conf'
20:40:34 [INFO] [exec] alembic.migration: INFO: Context impl SQLiteImpl.
20:40:34 [INFO] [exec] alembic.migration: INFO: Will assume non-transactional DDL.
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed.
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision.
20:40:34 [INFO] [exec] nxdrive.model: DEBUG: Set client version to 1.3-dev
20:40:34 [INFO] [exec] nxdrive.controller: INFO: nxdrive installed in '/Users/hudson/tmp/workspace/FT-nuxeo-drive-master-osx/nuxeo-drive-client/nxdrive'
20:40:34 [INFO] [exec] nxdrive.controller: INFO: nxdrive configured in '/private/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmp7OXggg-nxdrive-tests-user-2/nuxeo-drive-conf'
20:40:34 [INFO] [exec] alembic.migration: INFO: Context impl SQLiteImpl.
20:40:34 [INFO] [exec] alembic.migration: INFO: Will assume non-transactional DDL.
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed.
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6
20:40:34 [INFO] [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision.
20:40:34 [INFO] [exec] nxdrive.model: DEBUG: Set client version to 1.3-dev
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-administrator-device', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'} and cookies []
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"value": "/"}}'
20:40:34 [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":"f7985339-7540-4ab3-9e22-483d9e3ed05e","path":"/","type":"Root","state":null,"versionLabel":"","isCheckedOut":true,"title":"f7985339-7540-4ab3-9e22-483d9e3ed05e","properties":{"dc:creator":null,"dc:source":null,"dc:contributors":[],"dc:nature":null,"dc:created":null,"dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":null,"dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":null,"dc:lastContributor":null,"common:icon":null,"common:icon-expanded":null,"common:size":null},"facets":["Folderish","NotCollectionMember"],"changeToken":null,"contextParameters":{}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"userNames": "user_1, user_2", "permission": "ReadWrite"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests' with cookies [] has content-type 'text/plain'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"value": "/default-domain/workspaces/nuxeo-drive-test-workspace"}}'
20:40:34 [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":"6ea066ae-df13-42dd-8094-037250f68a9a","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-09T18:40:13.28Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-09-09T18:40:13.28Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:13.28Z","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":"1410288013284","contextParameters":{}}'
20:40:34 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='} and cookies []
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'6ea066ae-df13-42dd-8094-037250f68a9a'}}
20:40:34 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"params": {"value": "6ea066ae-df13-42dd-8094-037250f68a9a"}}'
20:40:34 [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":"6ea066ae-df13-42dd-8094-037250f68a9a","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-09T18:40:13.28Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-09-09T18:40:13.28Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:13.28Z","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":"1410288013284","contextParameters":{}}'
20:40:34 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo3YzU0OTY='} and cookies []
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'6ea066ae-df13-42dd-8094-037250f68a9a'}}
20:40:34 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo3YzU0OTY='}, cookies [] and JSON payload '{"params": {"value": "6ea066ae-df13-42dd-8094-037250f68a9a"}}'
20:40:34 [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":"6ea066ae-df13-42dd-8094-037250f68a9a","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-09T18:40:13.28Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator"],"dc:nature":null,"dc:created":"2014-09-09T18:40:13.28Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:13.28Z","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":"1410288013284","contextParameters":{}}'
20:40:34 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='} and cookies []
20:40:34 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo3YzU0OTY='} and cookies []
20:40:34 [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'bbfd8387385011e4b4d5002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='} and cookies []
20:40:34 [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=bbfd8387385011e4b4d5002500d3a152&permission=ReadWrite with headers {'X-Client-Version': '1.3-dev', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='} and cookies []
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Got token 'cc7ef080-ad35-43bd-9f36-65619f9efa4f' with cookies []
20:40:34 [INFO] [exec] nxdrive.controller: INFO: Binding '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive' to 'http://localhost:8080/nuxeo/' with account 'nuxeoDriveTestUser_user_1'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'} and cookies []
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {}}'
20:40:34 [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#","parentId":null,"lastModificationDate":765,"creationDate":765,"folder":true,"canDelete":false,"creator":"system","canRename":false,"userName":"nuxeoDriveTestUser_user_1"}'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '1970-01-01 01:00:00'
20:40:34 [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-09 20:40:13.768670
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {}}'
20:40:34 [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/"}'
20:40:34 [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/'}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'} and cookies []
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:6ea066ae-df13-42dd-8094-037250f68a9a', 'params': {'enable': True}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Authentication-Token': u'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', '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:6ea066ae-df13-42dd-8094-037250f68a9a", "params": {"enable": true}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
20:40:34 [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_update.docx', 'properties': 'dc:title=test_update.docx'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/", "params": {"type": "File", "name": "test_update.docx", "properties": "dc:title=test_update.docx"}}'
20:40:34 [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":"fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/test_update.docx","type":"File","state":"project","versionLabel":"0.0","isCheckedOut":true,"title":"test_update.docx","lastModified":"2014-09-09T18:40:13.91Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-09-09T18:40:13.91Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:13.91Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"test_update.docx","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":"1410288013915","contextParameters":{}}'
20:40:34 [INFO] [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.openxmlformats-officedocument.wordprocessingml.document' for 'test_update.docx'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 23, 'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'application/vnd.openxmlformats-officedocument.wordprocessingml.document', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 23, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1410288013.95_83346629', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'test_update.docx'} and cookies [] for file /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpO1DwOr-nxdrive-uploads/tmpbgep8j-nxdrive-file-to-upload
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1410288013.95_83346629"}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1410288013.95_83346629', 'document': u'fdbaf560-90c7-4cf8-9392-dcdaf15abfb0', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"params": {"batchId": "1410288013.95_83346629", "document": "fdbaf560-90c7-4cf8-9392-dcdaf15abfb0", "fileIdx": "0", "operationId": "Blob.Attach"}}'
20:40:34 [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.openxmlformats-officedocument.wordprocessingml.document'
20:40:34 [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_delete.docx', 'properties': 'dc:title=test_delete.docx'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/", "params": {"type": "File", "name": "test_delete.docx", "properties": "dc:title=test_delete.docx"}}'
20:40:34 [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":"b16af203-b880-40dd-90b8-25ab519e4422","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/test_delete.docx","type":"File","state":"project","versionLabel":"0.0","isCheckedOut":true,"title":"test_delete.docx","lastModified":"2014-09-09T18:40:14.04Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-09-09T18:40:14.04Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:14.04Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"test_delete.docx","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":"1410288014044","contextParameters":{}}'
20:40:34 [INFO] [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.openxmlformats-officedocument.wordprocessingml.document' for 'test_delete.docx'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 23, 'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'application/vnd.openxmlformats-officedocument.wordprocessingml.document', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 23, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1410288014.09_283942167', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'test_delete.docx'} and cookies [] for file /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpO1DwOr-nxdrive-uploads/tmpPdDwnQ-nxdrive-file-to-upload
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1410288014.09_283942167"}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1410288014.09_283942167', 'document': u'b16af203-b880-40dd-90b8-25ab519e4422', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"params": {"batchId": "1410288014.09_283942167", "document": "b16af203-b880-40dd-90b8-25ab519e4422", "fileIdx": "0", "operationId": "Blob.Attach"}}'
20:40:34 [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.openxmlformats-officedocument.wordprocessingml.document'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
20:40:34 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=19899)
20:40:34 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive: []
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":7294,"fileSystemChanges":[],"syncDate":1410288014000,"activeSynchronizationRootDefinitions":"default:6ea066ae-df13-42dd-8094-037250f68a9a","hasTooManyChanges":false}'
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote full scan of /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive. Reasons: forced: False, too many changes: False, first pass: True
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
20:40:34 [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#","parentId":null,"lastModificationDate":262,"creationDate":262,"folder":true,"canDelete":false,"creator":"system","canRename":false,"userName":"nuxeoDriveTestUser_user_1"}'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '1970-01-01 01:00:00', '1970-01-01 01:00:00'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
20:40:34 [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#6ea066ae-df13-42dd-8094-037250f68a9a","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1410288013856,"creationDate":1410288013284,"folder":true,"canDelete":true,"creator":"Administrator","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}]'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-09 20:40:13'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-09 20:40:13 and updated last_sync_date to 2014-09-09 20:40:14.295798
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-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'>
20:40:34 [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>
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-09 20:40:13', '2014-09-09 20:40:13'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', '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#6ea066ae-df13-42dd-8094-037250f68a9a"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"61520b8f760c930e8b499bd646790fad","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/fdbaf560-90c7-4cf8-9392-dcdaf15abfb0/blobholder:0/test_update.docx","canUpdate":true,"name":"test_update.docx","id":"defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288014012,"creationDate":1410288013915,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"},{"digest":"5bcebb84728fcb265ab1190944dc987a","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/b16af203-b880-40dd-90b8-25ab519e4422/blobholder:0/test_delete.docx","canUpdate":true,"name":"test_delete.docx","id":"defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288014114,"creationDate":1410288014044,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}]'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-09 20:40:14'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-09 20:40:14 and updated last_sync_date to 2014-09-09 20:40:14.338302
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'test_update.docx', local_state=None, remote_state=None, pair_state='unknown'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test_update.docx', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-09 20:40:14', '2014-09-09 20:40:14'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-09 20:40:14'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-09 20:40:14 and updated last_sync_date to 2014-09-09 20:40:14.349405
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'test_delete.docx', local_state=None, remote_state=None, pair_state='unknown'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'test_delete.docx', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-09 20:40:14', '2014-09-09 20:40:14'
20:40:34 [INFO] [exec] nxdrive.synchronizer: INFO: Watching FS modification on : /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', '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#6ea066ae-df13-42dd-8094-037250f68a9a"}}'
20:40:34 [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#6ea066ae-df13-42dd-8094-037250f68a9a","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","lastModificationDate":1410288013856,"creationDate":1410288013284,"folder":true,"canDelete":true,"creator":"Administrator","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-09 20:40:13', '2014-09-09 20:40:13'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/'
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Nuxeo Drive Test Workspace
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-09 20:40:13', '2014-09-09 20:40:13'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', '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#6ea066ae-df13-42dd-8094-037250f68a9a"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"61520b8f760c930e8b499bd646790fad","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/fdbaf560-90c7-4cf8-9392-dcdaf15abfb0/blobholder:0/test_update.docx","canUpdate":true,"name":"test_update.docx","id":"defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288014012,"creationDate":1410288013915,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"},{"digest":"5bcebb84728fcb265ab1190944dc987a","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/b16af203-b880-40dd-90b8-25ab519e4422/blobholder:0/test_delete.docx","canUpdate":true,"name":"test_delete.docx","id":"defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288014114,"creationDate":1410288014044,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}]'
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: 1 <DirModifiedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: 2 <DirCreatedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace', remote_name=u'Nuxeo Drive Test Workspace', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
20:40:34 [INFO] [exec] nxdrive.controller: INFO: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive: []
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"5bcebb84728fcb265ab1190944dc987a","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/b16af203-b880-40dd-90b8-25ab519e4422/blobholder:0/test_delete.docx","canUpdate":true,"name":"test_delete.docx","id":"defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288014114,"creationDate":1410288014044,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-09 20:40:14', '2014-09-09 20:40:14'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'test_delete.docx', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local file 'test_delete.docx' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"5bcebb84728fcb265ab1190944dc987a","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/b16af203-b880-40dd-90b8-25ab519e4422/blobholder:0/test_delete.docx","canUpdate":true,"name":"test_delete.docx","id":"defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288014114,"creationDate":1410288014044,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
20:40:34 [INFO] [exec] nxdrive.client.remote_file_system_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/b16af203-b880-40dd-90b8-25ab519e4422/blobholder:0/test_delete.docx' with headers: {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/test_delete.docx', remote_name=u'test_delete.docx', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
20:40:34 [INFO] [exec] nxdrive.controller: INFO: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive: [u'test_delete.docx']
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"61520b8f760c930e8b499bd646790fad","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/fdbaf560-90c7-4cf8-9392-dcdaf15abfb0/blobholder:0/test_update.docx","canUpdate":true,"name":"test_update.docx","id":"defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288014012,"creationDate":1410288013915,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-09 20:40:14', '2014-09-09 20:40:14'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'test_update.docx', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: 3 <FileCreatedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/test_delete.docx'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local file 'test_update.docx' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"61520b8f760c930e8b499bd646790fad","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/fdbaf560-90c7-4cf8-9392-dcdaf15abfb0/blobholder:0/test_update.docx","canUpdate":true,"name":"test_update.docx","id":"defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288014012,"creationDate":1410288013915,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
20:40:34 [INFO] [exec] nxdrive.client.remote_file_system_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/fdbaf560-90c7-4cf8-9392-dcdaf15abfb0/blobholder:0/test_update.docx' with headers: {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/test_update.docx', remote_name=u'test_update.docx', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
20:40:34 [INFO] [exec] nxdrive.controller: INFO: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive: [u'test_update.docx', u'test_delete.docx']
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 3, pending: 3, local: 0.028s, remote: 0.146s sync: 0.469s
20:40:34 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session
20:40:34 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x125970dd0>, ending any transaction in progress and releasing underlying connections from the pool
20:40:34 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'query': u"SELECT * FROM Document WHERE ecm:path = '/default-domain/workspaces/nuxeo-drive-test-workspace/test_update.docx' AND ecm:currentLifeCycleState != 'deleted' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Query with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:path = \'/default-domain/workspaces/nuxeo-drive-test-workspace/test_update.docx\' AND ecm:currentLifeCycleState != \'deleted\' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.Query' with cookies []: '{"entity-type":"documents","entries":[{"entity-type":"document","repository":"default","uid":"fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/test_update.docx","type":"File","state":"project","versionLabel":"0.0","isCheckedOut":true,"title":"test_update.docx","lastModified":"2014-09-09T18:40:14.01Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-09-09T18:40:13.91Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:14.01Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"test_update.docx","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"thumb:thumbnail":null,"common:icon":"/icons/docx.png","common:icon-expanded":null,"common:size":23,"file:content":{"name":"test_update.docx","mime-type":"application/vnd.openxmlformats-officedocument.wordprocessingml.document","encoding":null,"digest":"61520b8f760c930e8b499bd646790fad","length":"23","data":"http://localhost:8080/nuxeo/nxbigfile/default/fdbaf560-90c7-4cf8-9392-dcdaf15abfb0/file:content/test_update.docx"},"file:filename":null,"relatedtext:relatedtextresources":[]},"facets":["Downloadable","Commentable","Versionable","Publishable","HasRelatedText","Thumbnail"],"changeToken":"1410288014012","contextParameters":{}}]}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace/test_update.docx'}}
20:40:34 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"params": {"value": "/default-domain/workspaces/nuxeo-drive-test-workspace/test_update.docx"}}'
20:40:34 [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":"fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/test_update.docx","type":"File","state":"project","versionLabel":"0.0","isCheckedOut":true,"title":"test_update.docx","lastModified":"2014-09-09T18:40:14.01Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-09-09T18:40:13.91Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:14.01Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"test_update.docx","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"thumb:thumbnail":null,"common:icon":"/icons/docx.png","common:icon-expanded":null,"common:size":23,"file:content":{"name":"test_update.docx","mime-type":"application/vnd.openxmlformats-officedocument.wordprocessingml.document","encoding":null,"digest":"61520b8f760c930e8b499bd646790fad","length":"23","data":"http://localhost:8080/nuxeo/nxbigfile/default/fdbaf560-90c7-4cf8-9392-dcdaf15abfb0/file:content/test_update.docx"},"file:filename":null,"relatedtext:relatedtextresources":[]},"facets":["Downloadable","Commentable","Versionable","Publishable","HasRelatedText","Thumbnail"],"changeToken":"1410288014012","contextParameters":{}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
20:40:34 [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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"params": {"value": "/default-domain/workspaces/nuxeo-drive-test-workspace"}}'
20:40:34 [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":"6ea066ae-df13-42dd-8094-037250f68a9a","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-09-09T18:40:13.85Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:contributors":["Administrator","nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-09-09T18:40:13.28Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:13.85Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"drv:subscriptions":[{"enabled":true,"username":"nuxeoDriveTestUser_user_1","lastChangeDate":"2014-09-09T18:40:13.85Z"}],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:useCaptcha":null,"webc:welcomeText":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish","DriveSynchronized"],"changeToken":"1410288013856","contextParameters":{}}'
20:40:34 [INFO] [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.openxmlformats-officedocument.wordprocessingml.document' for 'test_update.docx'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 16, 'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'application/vnd.openxmlformats-officedocument.wordprocessingml.document', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 16, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1410288014.92_882705515', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'test_update.docx'} and cookies [] for file /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpO1DwOr-nxdrive-uploads/tmpP5Dl6o-nxdrive-file-to-upload
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1410288014.92_882705515"}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1410288014.92_882705515', 'document': u'/default-domain/workspaces/nuxeo-drive-test-workspace/test_update.docx', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"params": {"batchId": "1410288014.92_882705515", "document": "/default-domain/workspaces/nuxeo-drive-test-workspace/test_update.docx", "fileIdx": "0", "operationId": "Blob.Attach"}}'
20:40:34 [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.openxmlformats-officedocument.wordprocessingml.document'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:/default-domain/workspaces/nuxeo-drive-test-workspace/test_delete.docx', 'params': {'value': 'delete'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.SetLifeCycle with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/test_delete.docx", "params": {"value": "delete"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/Document.SetLifeCycle' with cookies []: '{"entity-type":"document","repository":"default","uid":"b16af203-b880-40dd-90b8-25ab519e4422","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/test_delete.docx","type":"File","state":"deleted","versionLabel":"0.0","isCheckedOut":true,"title":"test_delete.docx","lastModified":"2014-09-09T18:40:14.97Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-09-09T18:40:14.04Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:14.97Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"test_delete.docx","dc:lastContributor":"nuxeoDriveTestUser_user_1","files:files":[],"thumb:thumbnail":null,"common:icon":"/icons/docx.png","common:icon-expanded":null,"common:size":23,"file:content":{"name":"test_delete.docx","mime-type":"application/vnd.openxmlformats-officedocument.wordprocessingml.document","encoding":null,"digest":"5bcebb84728fcb265ab1190944dc987a","length":"23","data":"http://localhost:8080/nuxeo/nxbigfile/default/b16af203-b880-40dd-90b8-25ab519e4422/file:content/test_delete.docx"},"file:filename":null,"relatedtext:relatedtextresources":[]},"facets":["Downloadable","Commentable","Versionable","Publishable","HasRelatedText","Thumbnail"],"changeToken":"1410288014978","contextParameters":{}}'
20:40:34 [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': 'other.docx', 'properties': 'dc:title=other.docx'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/Document.Create with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"input": "doc:/default-domain/workspaces/nuxeo-drive-test-workspace/", "params": {"type": "File", "name": "other.docx", "properties": "dc:title=other.docx"}}'
20:40:34 [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":"face3501-3211-4356-b587-cbed37c20961","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/other.docx","type":"File","state":"project","versionLabel":"0.0","isCheckedOut":true,"title":"other.docx","lastModified":"2014-09-09T18:40:15.03Z","properties":{"uid:uid":null,"uid:minor_version":0,"uid:major_version":0,"dc:creator":"nuxeoDriveTestUser_user_1","dc:source":null,"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:nature":null,"dc:created":"2014-09-09T18:40:15.03Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-09-09T18:40:15.03Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"other.docx","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":"1410288015033","contextParameters":{}}'
20:40:34 [INFO] [exec] nxdrive.utils: TRACE: Guessed mime type 'application/vnd.openxmlformats-officedocument.wordprocessingml.document' for 'other.docx'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 1048576 bytes
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 14, 'X-Client-Version': '1.3-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'application/vnd.openxmlformats-officedocument.wordprocessingml.document', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 14, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1410288015.06_316475687', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'other.docx'} and cookies [] for file /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpO1DwOr-nxdrive-uploads/tmpmDCYFD-nxdrive-file-to-upload
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1410288015.06_316475687"}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1410288015.06_316475687', 'document': u'face3501-3211-4356-b587-cbed37c20961', 'fileIdx': '0', 'operationId': 'Blob.Attach'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/execute with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplYjlkYTE='}, cookies [] and JSON payload '{"params": {"batchId": "1410288015.06_316475687", "document": "face3501-3211-4356-b587-cbed37c20961", "fileIdx": "0", "operationId": "Blob.Attach"}}'
20:40:34 [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.openxmlformats-officedocument.wordprocessingml.document'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion with headers {'X-Client-Version': '1.3-dev', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
20:40:34 [INFO] [exec] nxdrive.synchronizer: INFO: Starting synchronization loop (pid=19899)
20:40:34 [INFO] [exec] nxdrive.controller: INFO: Initialized list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive: [u'test_update.docx', u'test_delete.docx']
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 7294, 'lastSyncActiveRootDefinitions': u'default:6ea066ae-df13-42dd-8094-037250f68a9a'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', '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": 7294, "lastSyncActiveRootDefinitions": "default:6ea066ae-df13-42dd-8094-037250f68a9a"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":7323,"fileSystemChanges":[{"fileSystemItem":{"digest":"39181c49e54b6e5ae8be13ab66f9fdb8","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/face3501-3211-4356-b587-cbed37c20961/blobholder:0/other.docx","canUpdate":true,"name":"other.docx","id":"defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288015086,"creationDate":1410288015033,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"eventId":"documentModified","eventDate":1410288015111,"repositoryId":"default","fileSystemItemId":"defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","fileSystemItemName":"other.docx","docUuid":"face3501-3211-4356-b587-cbed37c20961"},{"fileSystemItem":{"digest":"39181c49e54b6e5ae8be13ab66f9fdb8","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/face3501-3211-4356-b587-cbed37c20961/blobholder:0/other.docx","canUpdate":true,"name":"other.docx","id":"defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288015086,"creationDate":1410288015033,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"eventId":"documentCreated","eventDate":1410288015033,"repositoryId":"default","fileSystemItemId":"defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","fileSystemItemName":"other.docx","docUuid":"face3501-3211-4356-b587-cbed37c20961"},{"fileSystemItem":null,"eventId":"deleted","eventDate":1410288014983,"repositoryId":"default","fileSystemItemId":"defaultFileSystemItemFactory#default#b16af203-b880-40dd-90b8-25ab519e4422","fileSystemItemName":"test_delete.docx","docUuid":"b16af203-b880-40dd-90b8-25ab519e4422"},{"fileSystemItem":{"digest":"0788b34b5d5b3ff7ae0246e1ad99d62b","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/fdbaf560-90c7-4cf8-9392-dcdaf15abfb0/blobholder:0/test_update.docx","canUpdate":true,"name":"test_update.docx","id":"defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288014939,"creationDate":1410288013915,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"eventId":"documentModified","eventDate":1410288014962,"repositoryId":"default","fileSystemItemId":"defaultFileSystemItemFactory#default#fdbaf560-90c7-4cf8-9392-dcdaf15abfb0","fileSystemItemName":"test_update.docx","docUuid":"fdbaf560-90c7-4cf8-9392-dcdaf15abfb0"}],"syncDate":1410288015000,"activeSynchronizationRootDefinitions":"default:6ea066ae-df13-42dd-8094-037250f68a9a","hasTooManyChanges":false}'
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: 4 remote changes detected on http://localhost:8080/nuxeo/
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-09-09 20:40:15'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-09-09 20:40:15 and updated last_sync_date to 2014-09-09 20:40:15.280659
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'other.docx', local_state=None, remote_state=None, pair_state='unknown'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'other.docx', local_state='unknown', remote_state='unknown', pair_state='unknown', error_count=0>
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Marked doc_pair 'other.docx' as remote creation
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Marking doc_pair 'test_delete.docx' as deleted
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/test_delete.docx', remote_name=u'test_delete.docx', local_state=u'synchronized', remote_state='deleted', pair_state='remotely_deleted'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Refreshing remote state info for doc_pair 'test_update.docx'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-09 20:40:14', '2014-09-09 20:40:14'
20:40:34 [INFO] [exec] nxdrive.synchronizer: INFO: Watching FS modification on : /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: Handling test_delete.docx for deletion: last_local_updated = 2014-09-09 20:40:14, last_sync_date = 2014-09-09 20:40:14
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Deleting local file '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/test_delete.docx'
20:40:34 [INFO] [exec] nxdrive.client.local_client: INFO: Send /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/test_delete.docx to trash
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: 1 <FileDeletedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/test_delete.docx'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: 2 <DirModifiedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
20:40:34 [INFO] [exec] nxdrive.controller: INFO: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive: [u'test_update.docx']
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"39181c49e54b6e5ae8be13ab66f9fdb8","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/face3501-3211-4356-b587-cbed37c20961/blobholder:0/other.docx","canUpdate":true,"name":"other.docx","id":"defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288015086,"creationDate":1410288015033,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-09-09 20:40:15', '2014-09-09 20:40:15'
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=None, remote_name=u'other.docx', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Creating local file 'other.docx' in '/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961'}}
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961"}}'
20:40:34 [INFO] [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"39181c49e54b6e5ae8be13ab66f9fdb8","digestAlgorithm":"md5","downloadURL":"nxbigfile/default/face3501-3211-4356-b587-cbed37c20961/blobholder:0/other.docx","canUpdate":true,"name":"other.docx","id":"defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a/defaultFileSystemItemFactory#default#face3501-3211-4356-b587-cbed37c20961","parentId":"defaultSyncRootFolderItemFactory#default#6ea066ae-df13-42dd-8094-037250f68a9a","lastModificationDate":1410288015086,"creationDate":1410288015033,"folder":false,"canDelete":true,"creator":"nuxeoDriveTestUser_user_1","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
20:40:34 [INFO] [exec] nxdrive.client.remote_file_system_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/face3501-3211-4356-b587-cbed37c20961/blobholder:0/other.docx' with headers: {'X-Authentication-Token': 'cc7ef080-ad35-43bd-9f36-65619f9efa4f', 'X-Device-Id': u'bbfd8387385011e4b4d5002500d3a152', 'User-Agent': 'Nuxeo Drive/1.3-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3-dev'}
20:40:34 [INFO] [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/other.docx', remote_name=u'other.docx', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: 3 <FileCreatedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/other.docx'>
20:40:34 [INFO] [exec] nxdrive.synchronizer: TRACE: 4 <DirModifiedEvent: src_path='/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
20:40:34 [INFO] [exec] nxdrive.controller: INFO: Updated list of recently modified items in /var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive: [u'other.docx', u'test_update.docx']
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: [/var/folders/z2/0qcpf6l97tv6_pz56r7h67gm0000zd/T/tmpUMBt3g-nxdrive-tests-user-1/Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 2, pending: 2, local: 0.034s, remote: 0.135s sync: 1.056s
20:40:34 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping synchronization loop after 1 loops
20:40:34 [INFO] [exec] nxdrive.synchronizer: DEBUG: Calling Controller.dispose() from Synchronizer to close thread-local Session
20:40:34 [INFO] [exec] nxdrive.controller: DEBUG: Closing thread-local Session <sqlalchemy.orm.session.Session object at 0x125970dd0>, ending any transaction in progress and releasing underlying connections from the pool
20:40:34 [INFO] [exec] nxdrive.synchronizer: INFO: Stopping all FS Observers thread
20:40:34 [INFO] [exec] --------------------- >> end captured logging << ---------------------
- is required by
-
NXDRIVE-113 Random failure in test_integration_remote_move_and_rename.py", at line 114
-
- Resolved
-
-
NXDRIVE-69 Drive build safety check up
-
- Resolved
-
