[NXDRIVE-138] Random failure at line 462, in test_concurrent_remote_rename_folder - Nuxeo Issue Tracker

XML

Word

Printable

Details

Type: Bug
Status: Resolved
Priority: Minor
Resolution: Won't Fix
Affects Version/s: 1.3.1107
Fix Version/s: 1.4+
Component/s: Synchronizer, Tests

Tags:
- QAEmergency

Description

See:
http://qa.nuxeo.org/jenkins/job/FT-nuxeo-drive-master-linux/545/consoleFull
http://qa.nuxeo.org/jenkins/job/FT-nuxeo-drive-master-windows/473/consoleFull

Fails with:

09:56:34 [INFO]      [exec] ======================================================================
09:56:34 [INFO]      [exec] FAIL: test_concurrent_remote_rename_folder (nxdrive.tests.test_integration_remote_move_and_rename.TestIntegrationRemoteMoveAndRename)
09:56:34 [INFO]      [exec] ----------------------------------------------------------------------
09:56:34 [INFO]      [exec] Traceback (most recent call last):
09:56:34 [INFO]      [exec]   File "c:\hudson\workspace\FT-nuxeo-drive-master-windows\nuxeo-drive-client\nxdrive\tests\test_integration_remote_move_and_rename.py", line 462, in test_concurrent_remote_rename_folder
09:56:34 [INFO]      [exec]     self.assertEquals(ctl.synchronizer.update_synchronize_server(sb), 2)
09:56:34 [INFO]      [exec] AssertionError: 1 != 2
09:56:34 [INFO]      [exec] -------------------- >> begin captured logging << --------------------
09:56:34 [INFO]      [exec] nxdrive.controller: INFO: nxdrive installed in 'c:\hudson\workspace\FT-nuxeo-drive-master-windows\ftest\target\nxdrive_msi\SourceDir\appdata\nuxeo-drive-1.3.1103.win32\library.zip\nxdrive'
09:56:34 [INFO]      [exec] nxdrive.controller: INFO: nxdrive configured in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\nuxeo-drive-conf'
09:56:34 [INFO]      [exec] alembic.migration: INFO: Context impl SQLiteImpl.
09:56:34 [INFO]      [exec] alembic.migration: INFO: Will assume non-transactional DDL.
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed.
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision.
09:56:34 [INFO]      [exec] nxdrive.model: DEBUG: Set client version to 1.3.1103
09:56:34 [INFO]      [exec] nxdrive.controller: INFO: nxdrive installed in 'c:\hudson\workspace\FT-nuxeo-drive-master-windows\ftest\target\nxdrive_msi\SourceDir\appdata\nuxeo-drive-1.3.1103.win32\library.zip\nxdrive'
09:56:34 [INFO]      [exec] nxdrive.controller: INFO: nxdrive configured in 'c:\users\nuxeo\appdata\local\temp\tmpqaus53-nxdrive-tests-user-2\nuxeo-drive-conf'
09:56:34 [INFO]      [exec] alembic.migration: INFO: Context impl SQLiteImpl.
09:56:34 [INFO]      [exec] alembic.migration: INFO: Will assume non-transactional DDL.
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: Checking if SQLite database migration is needed.
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: Head Alembic revision: 2f126b5f61a6
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: Alembic is not initialized, setting current revision to head revision: 2f126b5f61a6
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: Current Alembic revision: 2f126b5f61a6
09:56:34 [INFO]      [exec] nxdrive.migration: DEBUG: No migration to process as current Alembic revision in SQLite database is already the head revision.
09:56:34 [INFO]      [exec] nxdrive.model: DEBUG: Set client version to 1.3.1103
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3.1103', 'X-Device-Id': u'nxdrive-test-administrator-device', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'} and cookies []
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/'}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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": "/"}}'
09:56: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":"7989bade-ac11-4e38-ab22-6cfdeaca3335","path":"/","type":"Root","state":null,"parentRef":"/","versionLabel":"","isCheckedOut":true,"title":"7989bade-ac11-4e38-ab22-6cfdeaca3335","properties":{"dc:creator":null,"dc:source":null,"dc:nature":null,"dc:contributors":[],"dc:created":null,"dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":null,"dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":null,"dc:lastContributor":null,"common:icon":null,"common:icon-expanded":null,"common:size":null},"facets":["Folderish","NotCollectionMember"],"changeToken":null,"contextParameters":{}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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"}}'
09:56: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'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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"}}'
09:56: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":"fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"cf7325b4-0038-47ce-95a1-3c993ed15952","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-11-03T08:53:57.02Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:nature":null,"dc:contributors":["Administrator"],"dc:created":"2014-11-03T08:53:57.02Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-11-03T08:53:57.02Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:welcomeText":null,"webc:useCaptcha":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1415004837026","contextParameters":{}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3.1103', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='} and cookies []
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"value": "fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56: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":"fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"cf7325b4-0038-47ce-95a1-3c993ed15952","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-11-03T08:53:57.02Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:nature":null,"dc:contributors":["Administrator"],"dc:created":"2014-11-03T08:53:57.02Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-11-03T08:53:57.02Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:welcomeText":null,"webc:useCaptcha":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1415004837026","contextParameters":{}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3.1103', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo0YWNjZmU='} and cookies []
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'value': u'fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-2', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo0YWNjZmU='}, cookies [] and JSON payload '{"params": {"value": "fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56: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":"fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"cf7325b4-0038-47ce-95a1-3c993ed15952","versionLabel":"","isCheckedOut":true,"title":"Nuxeo Drive Test Workspace","lastModified":"2014-11-03T08:53:57.02Z","properties":{"dc:creator":"Administrator","dc:source":null,"dc:nature":null,"dc:contributors":["Administrator"],"dc:created":"2014-11-03T08:53:57.02Z","dc:description":null,"dc:rights":null,"dc:subjects":[],"dc:publisher":null,"dc:valid":null,"dc:format":null,"dc:issued":null,"dc:modified":"2014-11-03T08:53:57.02Z","dc:expired":null,"dc:coverage":null,"dc:language":null,"dc:title":"Nuxeo Drive Test Workspace","dc:lastContributor":"Administrator","files:files":[],"common:icon":"/icons/workspace.gif","common:icon-expanded":null,"common:size":null,"file:content":null,"file:filename":null,"webc:welcomeText":null,"webc:useCaptcha":null,"webc:welcomeMedia":null,"webc:theme":"sites","webc:isWebContainer":null,"webc:baseline":null,"webc:template":null,"webc:logo":null,"webc:themePerspective":null,"webc:themePage":"workspace","webc:name":null,"webc:moderationType":"aposteriori","webc:url":null,"webc:email":null,"publish:sections":[]},"facets":["SuperSpace","Folderish"],"changeToken":"1415004837026","contextParameters":{}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3.1103', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='} and cookies []
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3.1103', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo0YWNjZmU='} and cookies []
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '1.3.1103', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='} and cookies []
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Windows+Desktop&revoke=false&deviceId=f2112070633611e4831e0024e814f531&permission=ReadWrite with headers {'X-Client-Version': '1.3.1103', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='} and cookies []
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Got token 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47' with cookies []
09:56:34 [INFO]      [exec] nxdrive.controller: INFO: Binding 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive' to 'http://localhost:8080/nuxeo/' with account 'nuxeoDriveTestUser_user_1'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3.1103'} and cookies []
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {}}'
09:56: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,"canRename":false,"canDelete":false,"creationDate":260,"lastModificationDate":260,"creator":"system","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/', remote_name=None, local_state=None, remote_state=None, pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '1970-01-01 01:00:00'
09:56: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-11-03 09:53:57.276000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/', remote_name=u'Nuxeo Drive', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {}}'
09:56: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/"}'
09:56: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/'}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': u'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3.1103'} and cookies []
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'input': u'doc:fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398', 'params': {'enable': True}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Authentication-Token': u'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"input": "doc:fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398", "params": {"enable": true}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":4489,"fileSystemChanges":[],"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","syncDate":1415004837000}'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote full scan of c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive. Reasons: forced: False, too many changes: False, first pass: True
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
09:56: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,"canRename":false,"canDelete":false,"creationDate":416,"lastModificationDate":416,"creator":"system","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56: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'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
09:56: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#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"creationDate":1415004837026,"lastModificationDate":1415004837338,"creator":"Administrator","folder":true,"userName":"nuxeoDriveTestUser_user_1"}]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-03 09:53:57 and updated last_sync_date to 2014-11-03 09:53:57.432000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=None, remote_state='modified', pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56: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='modified', pair_state='remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 1 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398', 'parentId': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398", "parentId": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
09:56: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#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"creationDate":1415004837026,"lastModificationDate":1415004837338,"creator":"Administrator","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-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'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Nuxeo Drive Test Workspace', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Nuxeo Drive Test Workspace' in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Nuxeo Drive Test Workspace
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-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'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: []
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: [c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.015s, remote: 0.078s sync: 0.063s
09:56:34 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'Original File 1.txt'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 14L, 'X-Client-Version': '1.3.1103', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'text/plain', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 14L, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1415004837.54_18471867', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%201.txt'} and cookies [] for file c:\users\nuxeo\appdata\local\temp\tmpd7vmx8-nxdrive-uploads\tmpmsnk3a-nxdrive-file-to-upload
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1415004837.54_18471867"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of NuxeoDrive.CreateFile with file c:\users\nuxeo\appdata\local\temp\tmpd7vmx8-nxdrive-uploads\tmpmsnk3a-nxdrive-file-to-upload
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1415004837.54_18471867', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398', 'fileIdx': '0', 'operationId': 'NuxeoDrive.CreateFile'}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"batchId": "1415004837.54_18471867", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398", "fileIdx": "0", "operationId": "NuxeoDrive.CreateFile"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/a87ed8f8-3e82-4e4d-87a5-69039f09f2a6/blobholder:0/Original%20File%201.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837557,"lastModificationDate":1415004837557,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'Original File 2.txt'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 14L, 'X-Client-Version': '1.3.1103', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'text/plain', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 14L, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1415004837.65_853146881', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%202.txt'} and cookies [] for file c:\users\nuxeo\appdata\local\temp\tmpd7vmx8-nxdrive-uploads\tmphg8hx0-nxdrive-file-to-upload
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1415004837.65_853146881"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of NuxeoDrive.CreateFile with file c:\users\nuxeo\appdata\local\temp\tmpd7vmx8-nxdrive-uploads\tmphg8hx0-nxdrive-file-to-upload
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1415004837.65_853146881', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398', 'fileIdx': '0', 'operationId': 'NuxeoDrive.CreateFile'}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"batchId": "1415004837.65_853146881", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398", "fileIdx": "0", "operationId": "NuxeoDrive.CreateFile"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies []: '{"digest":"aa5728d0861fd3b174dc33202838ecb8","downloadURL":"nxbigfile/default/bc96c818-0c64-49aa-be95-59df3d9a0b2e/blobholder:0/Original%20File%202.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837682,"lastModificationDate":1415004837682,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'name': u'Original Folder 1', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Client-Version': '1.3.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"name": "Original Folder 1", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"name":"Original Folder 1","id":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837744,"lastModificationDate":1415004837744,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'name': u'Sub-Folder 1.1', 'parentId': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Client-Version': '1.3.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"name": "Sub-Folder 1.1", "parentId": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"name":"Sub-Folder 1.1","id":"defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837806,"lastModificationDate":1415004837806,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'name': u'Sub-Folder 1.2', 'parentId': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Client-Version': '1.3.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"name": "Sub-Folder 1.2", "parentId": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"name":"Sub-Folder 1.2","id":"defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837869,"lastModificationDate":1415004837869,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'Original File 1.1.txt'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 14L, 'X-Client-Version': '1.3.1103', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'text/plain', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 14L, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1415004837.9_601504121', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%201.1.txt'} and cookies [] for file c:\users\nuxeo\appdata\local\temp\tmpd7vmx8-nxdrive-uploads\tmpjmwg4y-nxdrive-file-to-upload
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1415004837.9_601504121"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of NuxeoDrive.CreateFile with file c:\users\nuxeo\appdata\local\temp\tmpd7vmx8-nxdrive-uploads\tmpjmwg4y-nxdrive-file-to-upload
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1415004837.9_601504121', 'parentId': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc', 'fileIdx': '0', 'operationId': 'NuxeoDrive.CreateFile'}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"batchId": "1415004837.9_601504121", "parentId": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc", "fileIdx": "0", "operationId": "NuxeoDrive.CreateFile"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/ffc80f34-f546-42e0-8946-46020a458399/blobholder:0/Original%20File%201.1.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837931,"lastModificationDate":1415004837931,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'name': 'Original Folder 2', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Client-Version': '1.3.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"name": "Original Folder 2", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"name":"Original Folder 2","id":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004838009,"lastModificationDate":1415004838009,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.utils: TRACE: Guessed mime type 'text/plain' for 'Original File 3.txt'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using file system block size for the streaming upload buffer: 4096 bytes
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/batch/upload with headers {'Content-Length': 14L, 'X-Client-Version': '1.3.1103', 'X-Device-Id': u'nxdrive-test-device-1', 'X-File-Type': 'text/plain', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 14L, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU=', 'Cache-Control': 'no-cache', 'X-Batch-Id': '1415004838.04_159921883', 'X-File-Idx': 0, 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%203.txt'} and cookies [] for file c:\users\nuxeo\appdata\local\temp\tmpd7vmx8-nxdrive-uploads\tmpaq73j4-nxdrive-file-to-upload
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/upload' with cookies []: '{"uploaded":"true","batchId":"1415004838.04_159921883"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of NuxeoDrive.CreateFile with file c:\users\nuxeo\appdata\local\temp\tmpd7vmx8-nxdrive-uploads\tmpaq73j4-nxdrive-file-to-upload
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'batchId': '1415004838.04_159921883', 'parentId': u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2', 'fileIdx': '0', 'operationId': 'NuxeoDrive.CreateFile'}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"batchId": "1415004838.04_159921883", "parentId": "defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2", "fileIdx": "0", "operationId": "NuxeoDrive.CreateFile"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/batch/execute' with cookies []: '{"digest":"180b2cbf65a05357269e12a1d1324635","downloadURL":"nxbigfile/default/a5a9303d-7974-42bf-bd8f-7335c412bfa8/blobholder:0/Original%20File%203.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2/defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","parentId":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","canRename":true,"canDelete":true,"creationDate":1415004838072,"lastModificationDate":1415004838072,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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": {}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 4489, 'lastSyncActiveRootDefinitions': u'default:fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"lowerBound": 4489, "lastSyncActiveRootDefinitions": "default:fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":4515,"fileSystemChanges":[{"repositoryId":"default","fileSystemItem":{"digest":"180b2cbf65a05357269e12a1d1324635","downloadURL":"nxbigfile/default/a5a9303d-7974-42bf-bd8f-7335c412bfa8/blobholder:0/Original%20File%203.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2/defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","parentId":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","canRename":true,"canDelete":true,"creationDate":1415004838072,"lastModificationDate":1415004838072,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","fileSystemItemName":"Original File 3.txt","eventId":"documentCreated","eventDate":1415004838072,"docUuid":"a5a9303d-7974-42bf-bd8f-7335c412bfa8"},{"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Original Folder 2","id":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004838009,"lastModificationDate":1415004838009,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","fileSystemItemName":"Original Folder 2","eventId":"documentCreated","eventDate":1415004838009,"docUuid":"fe527a1f-5f80-48be-8284-61b2618ee3f2"},{"repositoryId":"default","fileSystemItem":{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/ffc80f34-f546-42e0-8946-46020a458399/blobholder:0/Original%20File%201.1.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837931,"lastModificationDate":1415004837931,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","fileSystemItemName":"Original File 1.1.txt","eventId":"documentCreated","eventDate":1415004837931,"docUuid":"ffc80f34-f546-42e0-8946-46020a458399"},{"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Sub-Folder 1.2","id":"defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837869,"lastModificationDate":1415004837869,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","fileSystemItemName":"Sub-Folder 1.2","eventId":"documentCreated","eventDate":1415004837869,"docUuid":"0a417d81-55fe-4fcb-a8e4-33627625149c"},{"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Sub-Folder 1.1","id":"defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837806,"lastModificationDate":1415004837806,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","fileSystemItemName":"Sub-Folder 1.1","eventId":"documentCreated","eventDate":1415004837806,"docUuid":"1c96b211-2656-4545-9ce7-32eeb9517fe8"},{"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Original Folder 1","id":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837744,"lastModificationDate":1415004837744,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","fileSystemItemName":"Original Folder 1","eventId":"documentCreated","eventDate":1415004837744,"docUuid":"79f04ec3-1252-423f-b0ab-10b3ab4482fc"},{"repositoryId":"default","fileSystemItem":{"digest":"aa5728d0861fd3b174dc33202838ecb8","downloadURL":"nxbigfile/default/bc96c818-0c64-49aa-be95-59df3d9a0b2e/blobholder:0/Original%20File%202.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837682,"lastModificationDate":1415004837682,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e","fileSystemItemName":"Original File 2.txt","eventId":"documentCreated","eventDate":1415004837682,"docUuid":"bc96c818-0c64-49aa-be95-59df3d9a0b2e"},{"repositoryId":"default","fileSystemItem":{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/a87ed8f8-3e82-4e4d-87a5-69039f09f2a6/blobholder:0/Original%20File%201.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837557,"lastModificationDate":1415004837557,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6","fileSystemItemName":"Original File 1.txt","eventId":"documentCreated","eventDate":1415004837557,"docUuid":"a87ed8f8-3e82-4e4d-87a5-69039f09f2a6"}],"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","syncDate":1415004838000}'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Updating remote states
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: 8 remote changes detected on http://localhost:8080/nuxeo/
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Could not match changed document to a bound local folder: RemoteFileInfo(name=u'Original File 3.txt', uid=u'defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8', parent_uid=u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2/defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8', folderish=False, last_modification_time=datetime.datetime(2014, 11, 3, 9, 53, 58), digest=u'180b2cbf65a05357269e12a1d1324635', digest_algorithm=u'md5', download_url=u'nxbigfile/default/a5a9303d-7974-42bf-bd8f-7335c412bfa8/blobholder:0/Original%20File%203.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-03 09:53:58 and updated last_sync_date to 2014-11-03 09:53:58.212000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state=None, remote_state='modified', pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marked doc_pair 'Original Folder 2' as remote creation
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Original Folder 2
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:58', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"180b2cbf65a05357269e12a1d1324635","downloadURL":"nxbigfile/default/a5a9303d-7974-42bf-bd8f-7335c412bfa8/blobholder:0/Original%20File%203.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2/defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","parentId":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","canRename":true,"canDelete":true,"creationDate":1415004838072,"lastModificationDate":1415004838072,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-03 09:53:58 and updated last_sync_date to 2014-11-03 09:53:58.228000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=None, remote_state='modified', pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:58', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Could not match changed document to a bound local folder: RemoteFileInfo(name=u'Original File 1.1.txt', uid=u'defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399', parent_uid=u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399', folderish=False, last_modification_time=datetime.datetime(2014, 11, 3, 9, 53, 57), digest=u'f3b09f7a82f6ac8c6077a1ca1d3778d8', digest_algorithm=u'md5', download_url=u'nxbigfile/default/ffc80f34-f546-42e0-8946-46020a458399/blobholder:0/Original%20File%201.1.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Could not match changed document to a bound local folder: RemoteFileInfo(name=u'Sub-Folder 1.2', uid=u'defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c', parent_uid=u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c', folderish=True, last_modification_time=datetime.datetime(2014, 11, 3, 9, 53, 57), digest=None, digest_algorithm=None, download_url=None, can_rename=True, can_delete=True, can_update=False, can_create_child=True)
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Could not match changed document to a bound local folder: RemoteFileInfo(name=u'Sub-Folder 1.1', uid=u'defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8', parent_uid=u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8', folderish=True, last_modification_time=datetime.datetime(2014, 11, 3, 9, 53, 57), digest=None, digest_algorithm=None, download_url=None, can_rename=True, can_delete=True, can_update=False, can_create_child=True)
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-03 09:53:57 and updated last_sync_date to 2014-11-03 09:53:58.259000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original Folder 1', local_state=None, remote_state='modified', pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original Folder 1', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 1', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marked doc_pair 'Original Folder 1' as remote creation
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Original Folder 1
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"name":"Sub-Folder 1.1","id":"defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837806,"lastModificationDate":1415004837806,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":true,"name":"Sub-Folder 1.2","id":"defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837869,"lastModificationDate":1415004837869,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/ffc80f34-f546-42e0-8946-46020a458399/blobholder:0/Original%20File%201.1.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837931,"lastModificationDate":1415004837931,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-03 09:53:57 and updated last_sync_date to 2014-11-03 09:53:58.290000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=None, remote_state='modified', pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-03 09:53:57 and updated last_sync_date to 2014-11-03 09:53:58.306000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=None, remote_state='modified', pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-03 09:53:57 and updated last_sync_date to 2014-11-03 09:53:58.337000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state=None, remote_state='modified', pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-03 09:53:57 and updated last_sync_date to 2014-11-03 09:53:58.352000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 2.txt', local_state=None, remote_state='modified', pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 2.txt', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 2.txt', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marked doc_pair 'Original File 2.txt' as remote creation
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = 'None', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: last_remote_updated is None for doc None, set it to 2014-11-03 09:53:57 and updated last_sync_date to 2014-11-03 09:53:58.368000
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 1.txt', local_state=None, remote_state='modified', pair_state='unknown'>
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 1.txt', local_state='unknown', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Created new pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.txt', local_state='unknown', remote_state='modified', pair_state='remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Marked doc_pair 'Original File 1.txt' as remote creation
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 8 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 2.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/a87ed8f8-3e82-4e4d-87a5-69039f09f2a6/blobholder:0/Original%20File%201.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837557,"lastModificationDate":1415004837557,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 1.txt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.txt', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local file 'Original File 1.txt' in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/a87ed8f8-3e82-4e4d-87a5-69039f09f2a6/blobholder:0/Original%20File%201.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#a87ed8f8-3e82-4e4d-87a5-69039f09f2a6","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837557,"lastModificationDate":1415004837557,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/a87ed8f8-3e82-4e4d-87a5-69039f09f2a6/blobholder:0/Original%20File%201.txt' with headers: {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3.1103'}
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original File 1.txt', remote_name=u'Original File 1.txt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: [u'Original File 1.txt']
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 7 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 2.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 2.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"aa5728d0861fd3b174dc33202838ecb8","downloadURL":"nxbigfile/default/bc96c818-0c64-49aa-be95-59df3d9a0b2e/blobholder:0/Original%20File%202.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837682,"lastModificationDate":1415004837682,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 2.txt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 2.txt', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local file 'Original File 2.txt' in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"aa5728d0861fd3b174dc33202838ecb8","downloadURL":"nxbigfile/default/bc96c818-0c64-49aa-be95-59df3d9a0b2e/blobholder:0/Original%20File%202.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#bc96c818-0c64-49aa-be95-59df3d9a0b2e","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837682,"lastModificationDate":1415004837682,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/bc96c818-0c64-49aa-be95-59df3d9a0b2e/blobholder:0/Original%20File%202.txt' with headers: {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3.1103'}
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original File 2.txt', remote_name=u'Original File 2.txt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: [u'Original File 2.txt', u'Original File 1.txt']
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 6 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Original Folder 1","id":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837744,"lastModificationDate":1415004837744,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original Folder 1', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 1', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Original Folder 1' in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Original Folder 1
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"name":"Sub-Folder 1.1","id":"defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837806,"lastModificationDate":1415004837806,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":true,"name":"Sub-Folder 1.2","id":"defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837869,"lastModificationDate":1415004837869,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/ffc80f34-f546-42e0-8946-46020a458399/blobholder:0/Original%20File%201.1.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837931,"lastModificationDate":1415004837931,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 1', remote_name=u'Original Folder 1', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: [u'Original File 2.txt', u'Original File 1.txt']
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 5 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Original Folder 2","id":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004838009,"lastModificationDate":1415004838009,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:58', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original Folder 2', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Original Folder 2' in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Original Folder 2
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:58', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"180b2cbf65a05357269e12a1d1324635","downloadURL":"nxbigfile/default/a5a9303d-7974-42bf-bd8f-7335c412bfa8/blobholder:0/Original%20File%203.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2/defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","parentId":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","canRename":true,"canDelete":true,"creationDate":1415004838072,"lastModificationDate":1415004838072,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 2', remote_name=u'Original Folder 2', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: [u'Original File 2.txt', u'Original File 1.txt']
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 4 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399', 'parentId': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399", "parentId": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/ffc80f34-f546-42e0-8946-46020a458399/blobholder:0/Original%20File%201.1.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837931,"lastModificationDate":1415004837931,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 1.1.txt', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local file 'Original File 1.1.txt' in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399', 'parentId': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399", "parentId": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/ffc80f34-f546-42e0-8946-46020a458399/blobholder:0/Original%20File%201.1.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837931,"lastModificationDate":1415004837931,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/ffc80f34-f546-42e0-8946-46020a458399/blobholder:0/Original%20File%201.1.txt' with headers: {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3.1103'}
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt', remote_name=u'Original File 1.1.txt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: [u'Original File 1.1.txt', u'Original File 2.txt', u'Original File 1.txt']
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 3 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8', 'parentId': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8", "parentId": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Sub-Folder 1.1","id":"defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837806,"lastModificationDate":1415004837806,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.1', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Sub-Folder 1.1' in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Sub-Folder 1.1
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1', remote_name=u'Sub-Folder 1.1', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: [u'Original File 1.1.txt', u'Original File 2.txt', u'Original File 1.txt']
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 2 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>, LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c', 'parentId': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c", "parentId": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Sub-Folder 1.2","id":"defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837869,"lastModificationDate":1415004837869,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Sub-Folder 1.2', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local folder 'Sub-Folder 1.2' in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Remote recursive scan of the content of Sub-Folder 1.2
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:57'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2', remote_name=u'Sub-Folder 1.2', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: [u'Original File 1.1.txt', u'Original File 2.txt', u'Original File 1.txt']
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 1 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8', 'parentId': u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8", "parentId": "defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"180b2cbf65a05357269e12a1d1324635","downloadURL":"nxbigfile/default/a5a9303d-7974-42bf-bd8f-7335c412bfa8/blobholder:0/Original%20File%203.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2/defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","parentId":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","canRename":true,"canDelete":true,"creationDate":1415004838072,"lastModificationDate":1415004838072,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:58', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state='created', pair_state='remotely_created'>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_created of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=None, remote_name=u'Original File 3.txt', local_state=u'unknown', remote_state=u'created', pair_state=u'remotely_created', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Creating local file 'Original File 3.txt' in 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8', 'parentId': u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8", "parentId": "defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"180b2cbf65a05357269e12a1d1324635","downloadURL":"nxbigfile/default/a5a9303d-7974-42bf-bd8f-7335c412bfa8/blobholder:0/Original%20File%203.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2/defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","parentId":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","canRename":true,"canDelete":true,"creationDate":1415004838072,"lastModificationDate":1415004838072,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling 'http://localhost:8080/nuxeo/nxbigfile/default/a5a9303d-7974-42bf-bd8f-7335c412bfa8/blobholder:0/Original%20File%203.txt' with headers: {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '1.3.1103'}
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', remote_name=u'Original File 3.txt', local_state='synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: [u'Original File 3.txt', u'Original File 1.1.txt', u'Original File 2.txt', u'Original File 1.txt']
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: [c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 8, pending: 8, local: 0.031s, remote: 0.218s sync: 0.499s
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc', 'name': u'Renamed Folder 1'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Rename with headers {'X-Client-Version': '1.3.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc", "name": "Renamed Folder 1"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Rename' with cookies []: '{"canCreateChild":true,"name":"Renamed Folder 1","id":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837744,"lastModificationDate":1415004838898,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Client-Version': '1.3.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Renamed Folder 1","id":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837744,"lastModificationDate":1415004838898,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2', 'name': u'Renamed Folder 2'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Rename with headers {'X-Client-Version': '1.3.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2", "name": "Renamed Folder 2"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Rename' with cookies []: '{"canCreateChild":true,"name":"Renamed Folder 2","id":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004838009,"lastModificationDate":1415004838961,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Client-Version': '1.3.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTo5NjZkYmU='}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Renamed Folder 2","id":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004838009,"lastModificationDate":1415004838961,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {}}
09:56: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.1103', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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": {}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.WaitForAsyncCompletion' with cookies [] has content-type ''
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Fetching remote change summary
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'lowerBound': 4515, 'lastSyncActiveRootDefinitions': u'default:fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"lowerBound": 4515, "lastSyncActiveRootDefinitions": "default:fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"upperBound":4547,"fileSystemChanges":[{"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Renamed Folder 2","id":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004838009,"lastModificationDate":1415004838961,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","fileSystemItemName":"Renamed Folder 2","eventId":"documentModified","eventDate":1415004838961,"docUuid":"fe527a1f-5f80-48be-8284-61b2618ee3f2"},{"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"name":"Renamed Folder 1","id":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837744,"lastModificationDate":1415004838898,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","fileSystemItemName":"Renamed Folder 1","eventId":"documentModified","eventDate":1415004838898,"docUuid":"79f04ec3-1252-423f-b0ab-10b3ab4482fc"}],"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","syncDate":1415004839000}'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Updating remote states
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: 2 remote changes detected on http://localhost:8080/nuxeo/
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Refreshing remote state info for doc_pair 'Original Folder 2'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:58', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"180b2cbf65a05357269e12a1d1324635","downloadURL":"nxbigfile/default/a5a9303d-7974-42bf-bd8f-7335c412bfa8/blobholder:0/Original%20File%203.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2/defaultFileSystemItemFactory#default#a5a9303d-7974-42bf-bd8f-7335c412bfa8","parentId":"defaultFileSystemItemFactory#default#fe527a1f-5f80-48be-8284-61b2618ee3f2","canRename":true,"canDelete":true,"creationDate":1415004838072,"lastModificationDate":1415004838072,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Refreshing remote state info for doc_pair 'Original Folder 1'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:57', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Doc Original Folder 1 has been either modified, renamed, moved or restored from the trash, set last_remote_updated to 2014-11-03 09:53:58
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Doc Original Folder 1 is a folder that has been renamed or moved, set remote_state to 'modified'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 1', remote_name=u'Renamed Folder 1', local_state=u'synchronized', remote_state='modified', pair_state='remotely_modified'>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"name":"Sub-Folder 1.1","id":"defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#1c96b211-2656-4545-9ce7-32eeb9517fe8","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837806,"lastModificationDate":1415004837806,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},{"canCreateChild":true,"name":"Sub-Folder 1.2","id":"defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#0a417d81-55fe-4fcb-a8e4-33627625149c","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837869,"lastModificationDate":1415004837869,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"},{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","downloadURL":"nxbigfile/default/ffc80f34-f546-42e0-8946-46020a458399/blobholder:0/Original%20File%201.1.txt","digestAlgorithm":"md5","canUpdate":true,"name":"Original File 1.1.txt","id":"defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc/defaultFileSystemItemFactory#default#ffc80f34-f546-42e0-8946-46020a458399","parentId":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","canRename":true,"canDelete":true,"creationDate":1415004837931,"lastModificationDate":1415004837931,"creator":"nuxeoDriveTestUser_user_1","folder":false,"userName":"nuxeoDriveTestUser_user_1"}]'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Processing local scan to detect local changes
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Found 1 pending items
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Pending items: [LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 1', remote_name=u'Renamed Folder 1', local_state=u'synchronized', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>]
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Synchronizing doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 1', remote_name=u'Renamed Folder 1', local_state=u'synchronized', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc', 'parentId': u'defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398'}}
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'c07feca3-47f0-4ea8-bb8b-d3d2a1347e47', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'f2112070633611e4831e0024e814f531', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/1.3.1103', '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.1103'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc", "parentId": "defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398"}}'
09:56:34 [INFO]      [exec] nxdrive.client.base_automation_client: TRACE: Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Renamed Folder 1","id":"defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398/defaultFileSystemItemFactory#default#79f04ec3-1252-423f-b0ab-10b3ab4482fc","parentId":"defaultSyncRootFolderItemFactory#default#fd28bf3d-8ba4-4347-bb10-ee1b1aeaf398","canRename":true,"canDelete":true,"creationDate":1415004837744,"lastModificationDate":1415004838898,"creator":"nuxeoDriveTestUser_user_1","folder":true,"userName":"nuxeoDriveTestUser_user_1"}'
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Use last known modification time to detect updates: local DB, server = '2014-11-03 09:53:58', '2014-11-03 09:53:58'
09:56:34 [INFO]      [exec] nxdrive.synchronizer: TRACE: Calling <bound method Synchronizer._synchronize_remotely_modified of <nxdrive.synchronizer.Synchronizer object at 0x1BE58470>> on doc pair LastKnownState<local_folder=u'Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Original Folder 1', remote_name=u'Renamed Folder 1', local_state=u'synchronized', remote_state=u'modified', pair_state=u'remotely_modified', error_count=0>
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: Renaming local folder 'c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1' to 'Renamed Folder 1'.
09:56:34 [INFO]      [exec] nxdrive.model: TRACE: Updated state for LastKnownState<local_folder=u'c:\\users\\nuxeo\\appdata\\local\\temp\\tmp1dp9tq-nxdrive-tests-user-1\\Nuxeo Drive', local_path=u'/Nuxeo Drive Test Workspace/Renamed Folder 1', remote_name=u'Renamed Folder 1', local_state=u'synchronized', remote_state='synchronized', pair_state='synchronized'>
09:56:34 [INFO]      [exec] nxdrive.controller: TRACE: Updated list of recently modified items in c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive: [u'Original File 3.txt', u'Original File 1.1.txt', u'Original File 2.txt', u'Original File 1.txt']
09:56:34 [INFO]      [exec] nxdrive.synchronizer: DEBUG: [c:\users\nuxeo\appdata\local\temp\tmp1dp9tq-nxdrive-tests-user-1\Nuxeo Drive] - [http://localhost:8080/nuxeo/]: synchronized: 1, pending: 1, local: 0.047s, remote: 0.109s sync: 0.078s
09:56:34 [INFO]      [exec] --------------------- >> end captured logging << ---------------------

Attachments

Activity

People

Assignee:

Antoine Taillefer

Reporter:

Antoine Taillefer

Participants:

Antoine Taillefer

Votes:

0 Vote for this issue

Watchers:

1 Start watching this issue

Dates

Created:

2014-11-03 09:18

Updated:

2015-02-27 16:02

Resolved:

2015-02-27 16:02