Minor Was leading to a systematic failure at line 369, in test_concurrent_local_rename_folder, see trace below.
Now fixed in the tests, but need to fix this corner case.
10:22:49 [INFO] [exec] ======================================================================
10:22:49 [INFO] [exec] ERROR: test_concurrent_local_rename_folder (nxdrive.tests.test_local_move_and_rename.TestLocalMoveAndRename)
10:22:49 [INFO] [exec] ----------------------------------------------------------------------
10:22:49 [INFO] [exec] Traceback (most recent call last):
10:22:49 [INFO] [exec] File "C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\nuxeo-drive-client\nxdrive\tests\test_local_move_and_rename.py", line 369, in test_concurrent_local_rename_folder
10:22:49 [INFO] [exec] folder_1_uid = remote_client.get_info(u'/Original Folder 1').uid
10:22:49 [INFO] [exec] File "C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\nuxeo-drive-client\nxdrive\client\remote_document_client.py", line 100, in get_info
10:22:49 [INFO] [exec] self._check_ref(ref), self.server_url))
10:22:49 [INFO] [exec] NotFound: Could not find '/default-domain/workspaces/nuxeo-drive-test-workspace/Original Folder 1' on 'http://localhost:8080/nuxeo/'
10:22:49 [INFO] [exec] -------------------- >> begin captured logging << --------------------
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,392 2992 DEBUG nxdrive.engine.dao.sqlite Create DAO on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\nuxeo-drive-conf\manager.db
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,392 2992 DEBUG nxdrive.engine.dao.sqlite Create main connexion on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\nuxeo-drive-conf\manager.db (dir exists: 1 / file exists: 0)
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,407 2992 DEBUG nxdrive.osi Using Windows OS integration
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,413 2992 DEBUG nxdrive.updater Application is frozen, building Esky instance from executable C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\ftest\target\nxdrive_msi\SourceDir\appdata\nuxeo-drive-2.0.1120.win32\ndrive.exe and version finder http://community.nuxeo.com/static/drive/
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,417 2992 DEBUG nxdrive.engine.dao.sqlite Create DAO on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpronryz-nxdrive-tests-user-2\nuxeo-drive-conf\manager.db
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,417 2992 DEBUG nxdrive.engine.dao.sqlite Create main connexion on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpronryz-nxdrive-tests-user-2\nuxeo-drive-conf\manager.db (dir exists: 1 / file exists: 0)
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,430 2992 DEBUG nxdrive.osi Using Windows OS integration
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,434 2992 DEBUG nxdrive.updater Application is frozen, building Esky instance from executable C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\ftest\target\nxdrive_msi\SourceDir\appdata\nuxeo-drive-2.0.1120.win32\ndrive.exe and version finder http://community.nuxeo.com/static/drive/
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,437 2992 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,437 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-administrator-device', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,470 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,470 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"value": "/"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,479 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"3035b233-7a5c-4dba-a3ba-53a45fa80062","path":"/","type":"Root","state":null,"parentRef":"/","isCheckedOut":true,"changeToken":null,"title":"3035b233-7a5c-4dba-a3ba-53a45fa80062","properties":{"common:size":null,"common:icon-expanded":null,"common:icon":null,"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":null,"dc:modified":null,"dc:lastContributor":null,"dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":null,"dc:title":null,"dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":[],"dc:source":null,"dc:publisher":null},"facets":["Folderish","NotCollectionMember"]}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,479 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,479 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"userNames": "user_1, user_2", "permission": "ReadWrite"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,575 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetupIntegrationTests' with cookies [] has content-type 'text/plain;charset=UTF-8'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,582 2992 DEBUG nxdrive.engine.dao.sqlite Create DAO on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\nuxeo-drive-conf\ndrive_3d7f1ea18f6811e59cf80800279ce356.db
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,582 2992 DEBUG nxdrive.engine.dao.sqlite Create main connexion on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\nuxeo-drive-conf\ndrive_3d7f1ea18f6811e59cf80800279ce356.db (dir exists: 1 / file exists: 0)
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,598 2992 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,602 2992 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite finished
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,604 2992 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,604 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplMmM2ZTU='} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,648 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Windows+Desktop&revoke=false&deviceId=3d65a3308f6811e5bd650800279ce356&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplMmM2ZTU='} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,657 2992 TRACE nxdrive.client.base_automation_client Got token '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995' with cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,667 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,667 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,676 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"8.1-SNAPSHOT","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/","updateSiteURL":"http://community.nuxeo.com/static/drive/"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,677 2992 DEBUG nxdrive.engine.engine Fetched update info for engine [localhost] from server http://localhost:8080/nuxeo/: {u'serverVersion': u'8.1-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/', u'betaUpdateSiteURL': u'http://community.nuxeo.com/static/drive-tests/'}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,687 2992 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,687 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,714 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,716 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,723 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":721,"lastContributor":"system","lastModificationDate":721,"folder":true,"creator":"system","canDelete":false,"parentId":null,"canRename":false,"userName":"nuxeoDriveTestUser_user_1"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,724 2992 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,730 2992 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,730 2992 TRACE nxdrive.client.local_client Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_1|3d65a3308f6811e5bd650800279ce356|3d7f1ea18f6811e59cf80800279ce356' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,730 2992 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,733 2992 DEBUG nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[1](Local: u'/', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,737 2992 DEBUG nxdrive.engine.watcher.local_watcher Windows detected so delete event will be delayed by 2000ms
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,743 2992 DEBUG nxdrive.engine.dao.sqlite Create DAO on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpronryz-nxdrive-tests-user-2\nuxeo-drive-conf\ndrive_3d97fdcf8f6811e5aae90800279ce356.db
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,743 2992 DEBUG nxdrive.engine.dao.sqlite Create main connexion on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpronryz-nxdrive-tests-user-2\nuxeo-drive-conf\ndrive_3d97fdcf8f6811e5aae90800279ce356.db (dir exists: 1 / file exists: 0)
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,759 2992 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,763 2992 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite finished
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,763 2992 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,765 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '3d68fe918f6811e589a10800279ce356', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjoyNDM3M2M='} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,796 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Windows+Desktop&revoke=false&deviceId=3d68fe918f6811e589a10800279ce356&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '3d68fe918f6811e589a10800279ce356', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjoyNDM3M2M='} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,805 2992 TRACE nxdrive.client.base_automation_client Got token '25949b72-13a7-4166-866f-f178daf85b3a' with cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,812 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,812 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '25949b72-13a7-4166-866f-f178daf85b3a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d68fe918f6811e589a10800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,822 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"8.1-SNAPSHOT","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/","updateSiteURL":"http://community.nuxeo.com/static/drive/"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,823 2992 DEBUG nxdrive.engine.engine Fetched update info for engine [localhost] from server http://localhost:8080/nuxeo/: {u'serverVersion': u'8.1-SNAPSHOT', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/', u'betaUpdateSiteURL': u'http://community.nuxeo.com/static/drive-tests/'}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,832 2992 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,832 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '25949b72-13a7-4166-866f-f178daf85b3a', 'X-Device-Id': '3d68fe918f6811e589a10800279ce356', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,864 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,864 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '25949b72-13a7-4166-866f-f178daf85b3a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d68fe918f6811e589a10800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,874 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":871,"lastContributor":"system","lastModificationDate":871,"folder":true,"creator":"system","canDelete":false,"parentId":null,"canRename":false,"userName":"nuxeoDriveTestUser_user_2"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,875 2992 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,881 2992 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,881 2992 TRACE nxdrive.client.local_client Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_2|3d68fe918f6811e589a10800279ce356|3d97fdcf8f6811e5aae90800279ce356' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpronryz-nxdrive-tests-user-2\\Nuxeo Drive'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,882 2992 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,884 2992 DEBUG nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[1](Local: u'/', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,888 2992 DEBUG nxdrive.engine.watcher.local_watcher Windows detected so delete event will be delayed by 2000ms
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,891 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,891 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-administrator-device', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': 'Administrator', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpBZG1pbmlzdHJhdG9y'}, cookies [] and JSON payload '{"params": {"value": "/default-domain/workspaces/nuxeo-drive-test-workspace"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,910 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"70bfb84f-acab-40e5-8a6a-698a8e55ea40","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"a90ffb5f-cf02-4f3a-bc28-1cae125a4ab4","isCheckedOut":true,"changeToken":"1448011357510","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-20T09:22:37.51Z","properties":{"webc:themePerspective":null,"webc:useCaptcha":null,"webc:isWebContainer":null,"webc:template":null,"webc:themePage":"workspace","webc:logo":null,"webc:name":null,"webc:email":null,"webc:welcomeMedia":null,"webc:url":null,"webc:baseline":null,"webc:theme":"sites","webc:moderationType":"aposteriori","webc:welcomeText":null,"file:filename":null,"file:content":null,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/workspace.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"Administrator","dc:modified":"2015-11-20T09:22:37.51Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-20T09:22:37.51Z","dc:title":"Nuxeo Drive Test Workspace","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["Administrator"],"dc:source":null,"dc:publisher":null,"publish:sections":[]},"facets":["Folderish","SuperSpace"]}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,911 2992 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,911 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplMmM2ZTU='} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,940 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'70bfb84f-acab-40e5-8a6a-698a8e55ea40'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,940 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplMmM2ZTU='}, cookies [] and JSON payload '{"params": {"value": "70bfb84f-acab-40e5-8a6a-698a8e55ea40"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,947 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"70bfb84f-acab-40e5-8a6a-698a8e55ea40","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"a90ffb5f-cf02-4f3a-bc28-1cae125a4ab4","isCheckedOut":true,"changeToken":"1448011357510","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-20T09:22:37.51Z","properties":{"webc:themePerspective":null,"webc:useCaptcha":null,"webc:isWebContainer":null,"webc:template":null,"webc:themePage":"workspace","webc:logo":null,"webc:name":null,"webc:email":null,"webc:welcomeMedia":null,"webc:url":null,"webc:baseline":null,"webc:theme":"sites","webc:moderationType":"aposteriori","webc:welcomeText":null,"file:filename":null,"file:content":null,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/workspace.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"Administrator","dc:modified":"2015-11-20T09:22:37.51Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-20T09:22:37.51Z","dc:title":"Nuxeo Drive Test Workspace","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["Administrator"],"dc:source":null,"dc:publisher":null,"publish:sections":[]},"facets":["Folderish","SuperSpace"]}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,950 2992 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,950 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjoyNDM3M2M='} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,976 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'70bfb84f-acab-40e5-8a6a-698a8e55ea40'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,976 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/Document.Fetch with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-2', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjoyNDM3M2M='}, cookies [] and JSON payload '{"params": {"value": "70bfb84f-acab-40e5-8a6a-698a8e55ea40"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,984 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"70bfb84f-acab-40e5-8a6a-698a8e55ea40","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"a90ffb5f-cf02-4f3a-bc28-1cae125a4ab4","isCheckedOut":true,"changeToken":"1448011357510","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-20T09:22:37.51Z","properties":{"webc:themePerspective":null,"webc:useCaptcha":null,"webc:isWebContainer":null,"webc:template":null,"webc:themePage":"workspace","webc:logo":null,"webc:name":null,"webc:email":null,"webc:welcomeMedia":null,"webc:url":null,"webc:baseline":null,"webc:theme":"sites","webc:moderationType":"aposteriori","webc:welcomeText":null,"file:filename":null,"file:content":null,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/workspace.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"Administrator","dc:modified":"2015-11-20T09:22:37.51Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-20T09:22:37.51Z","dc:title":"Nuxeo Drive Test Workspace","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["Administrator"],"dc:source":null,"dc:publisher":null,"publish:sections":[]},"facets":["Folderish","SuperSpace"]}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,986 2992 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:37,986 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-1', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplMmM2ZTU='} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:38,010 2992 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:38,010 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': u'nxdrive-test-device-2', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjoyNDM3M2M='} and cookies []
10:22:49 [INFO] [exec] 2015-11-20 10:22:38,036 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'input': u'doc:70bfb84f-acab-40e5-8a6a-698a8e55ea40', 'params': {'enable': True}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:38,036 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplMmM2ZTU='}, cookies [] and JSON payload '{"input": "doc:70bfb84f-acab-40e5-8a6a-698a8e55ea40", "params": {"enable": true}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:38,114 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
10:22:49 [INFO] [exec] 2015-11-20 10:22:38,114 2992 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'input': u'doc:70bfb84f-acab-40e5-8a6a-698a8e55ea40', 'params': {'enable': True}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:38,115 2992 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-2', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_2', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjoyNDM3M2M='}, cookies [] and JSON payload '{"input": "doc:70bfb84f-acab-40e5-8a6a-698a8e55ea40", "params": {"enable": true}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:38,203 2992 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
10:22:49 [INFO] [exec] 2015-11-20 10:22:38,204 1684 DEBUG nxdrive.tests.common_unit_test UnitTest thread started
10:22:49 [INFO] [exec] 2015-11-20 10:22:39,207 1684 TRACE nxdrive.client.local_client Setting xattr drive-fs-test with value 'NXDRIVE_VERIFICATION' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive'
10:22:49 [INFO] [exec] 2015-11-20 10:22:39,210 1684 TRACE nxdrive.client.local_client Removing xattr drive-fs-test from \\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive
10:22:49 [INFO] [exec] 2015-11-20 10:22:39,211 1684 DEBUG nxdrive.engine.engine Engine start
10:22:49 [INFO] [exec] 2015-11-20 10:22:39,216 2708 DEBUG nxdrive.engine.workers Thread LocalWatcher(2708) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:39,220 2708 DEBUG nxdrive.engine.watcher.local_watcher Watching FS modification on : C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive
10:22:49 [INFO] [exec] 2015-11-20 10:22:39,229 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:39,240 1684 DEBUG nxdrive.tests.common_unit_test Wait for sync
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,233 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,233 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,233 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,236 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,240 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,249 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,250 2708 DEBUG nxdrive.engine.watcher.local_watcher Watchdog setup finished
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,255 2708 DEBUG nxdrive.engine.watcher.local_watcher Full scan started
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,262 2708 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,262 2820 TRACE nxdrive.engine.watcher.local_watcher DriveFSROOT: Nuxeo Drive : need: Nuxeo Drive
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,267 2708 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,267 2708 TRACE nxdrive.engine.queue_manager Pushing QueueItem[2](Folderish:True, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,267 2708 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,276 2708 DEBUG nxdrive.engine.watcher.local_watcher Found new file /Nuxeo Drive Test Workspace/Original File 1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,282 2708 DEBUG nxdrive.engine.watcher.local_watcher Found new file /Nuxeo Drive Test Workspace/Original File 2.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,288 2708 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace/Original Folder 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,292 2708 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace/Original Folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,298 2708 DEBUG nxdrive.engine.watcher.local_watcher Found new file /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,302 2708 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,303 2708 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,308 2708 DEBUG nxdrive.engine.watcher.local_watcher Found new file /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,312 2708 DEBUG nxdrive.engine.watcher.local_watcher Full scan finished in 58ms
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,315 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,315 2976 DEBUG nxdrive.engine.workers Thread RemoteWatcher(2976) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,318 2992 DEBUG nxdrive.engine.queue_manager creating local folder processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,321 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,322 1120 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(1120) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,323 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,328 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,329 2976 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=True
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,336 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,339 1120 TRACE nxdrive.engine.dao.sqlite Acquired processor 1120 for row 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,341 2976 DEBUG nxdrive.engine.watcher.remote_watcher Remote full scan
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,355 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1, remote_ref=None]
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,359 2976 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,358 1120 DEBUG nxdrive.engine.processor Executing processor on StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,362 2708 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,364 2976 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,368 2708 TRACE nxdrive.engine.queue_manager Pushing QueueItem[5](Folderish:True, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,368 1120 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B29E0>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,375 1120 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,375 2708 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,384 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,384 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,391 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1\Sub-Folder 1.1, remote_ref=None]
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,391 1120 WARNING nxdrive.engine.processor Won't synchronize folder 'Nuxeo Drive Test Workspace' created in local folder '' since it is readonly
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,395 1120 DEBUG nxdrive.engine.processor Set pair unsynchronized: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,398 2708 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: StateRow[8](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,401 2976 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","creationDate":387,"lastContributor":"system","lastModificationDate":387,"folder":true,"creator":"system","canDelete":false,"parentId":null,"canRename":false,"userName":"nuxeoDriveTestUser_user_1"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,401 1120 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace, remote_name=None, version=0] with version=0
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,404 2708 TRACE nxdrive.engine.queue_manager Pushing QueueItem[8](Folderish:True, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,407 2976 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Nuxeo Drive', uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', parent_uid=None, path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', folderish=True, last_modification_time=datetime.datetime(1970, 1, 1, 1, 0), last_contributor=u'system', digest=None, digest_algorithm=None, download_url=None, can_rename=False, can_delete=False, can_update=False, can_create_child=False)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,408 2708 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,418 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,420 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,421 1120 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B29E0>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,424 1120 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,427 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1\Sub-Folder 1.2, remote_ref=None]
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,430 2976 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,430 2976 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,431 2976 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,434 1120 TRACE nxdrive.engine.dao.sqlite Released processor 1120
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,440 2708 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: StateRow[9](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,440 2708 TRACE nxdrive.engine.queue_manager Pushing QueueItem[9](Folderish:True, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,441 2708 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,447 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,447 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,450 1120 TRACE nxdrive.engine.dao.sqlite Acquired processor 1120 for row 5
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,450 1120 DEBUG nxdrive.engine.processor Executing processor on StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,451 1120 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B29E0>> on doc pair StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,451 1120 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,453 1120 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 1, remote_name=None, version=1] with version=1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,457 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1\Original File 1.1.txt, remote_ref=None]
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,459 1120 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B29E0>> on doc pair StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,461 2708 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: StateRow[7](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,461 1120 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,463 2708 TRACE nxdrive.engine.queue_manager Pushing QueueItem[7](Folderish:False, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,466 2708 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,470 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,470 1120 TRACE nxdrive.engine.dao.sqlite Released processor 1120
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,471 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,480 1120 TRACE nxdrive.engine.dao.sqlite Acquired processor 1120 for row 8
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,480 1120 DEBUG nxdrive.engine.processor Executing processor on StateRow[8](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,482 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,483 1120 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B29E0>> on doc pair StateRow[8](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,484 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,484 1120 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,490 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,493 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,493 1120 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1, remote_name=None, version=1] with version=1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,496 2708 TRACE nxdrive.engine.watcher.local_watcher Don't update as in process StateRow[8](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,500 1120 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B29E0>> on doc pair StateRow[8](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,502 1120 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1/sub-folder 1.1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,502 1120 TRACE nxdrive.engine.dao.sqlite Released processor 1120
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,505 1120 TRACE nxdrive.engine.dao.sqlite Acquired processor 1120 for row 9
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,505 1120 DEBUG nxdrive.engine.processor Executing processor on StateRow[9](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,506 1120 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B29E0>> on doc pair StateRow[9](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,506 1120 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,506 1120 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2, remote_name=None, version=1] with version=1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,509 1120 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B29E0>> on doc pair StateRow[9](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,509 1120 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1/sub-folder 1.2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,509 1120 TRACE nxdrive.engine.dao.sqlite Released processor 1120
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,509 1120 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(1120) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,523 2976 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"fileSystemChanges":[],"upperBound":1301,"syncDate":1448011360000,"activeSynchronizationRootDefinitions":"default:70bfb84f-acab-40e5-8a6a-698a8e55ea40"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,529 2976 DEBUG nxdrive.engine.watcher.remote_watcher Remote scanning: /
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,529 2976 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,530 2976 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,546 2976 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40","creationDate":1448011357510,"lastContributor":"nuxeoDriveTestUser_user_2","lastModificationDate":1448011358185,"folder":true,"creator":"Administrator","canDelete":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}]'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,546 2976 TRACE nxdrive.engine.watcher.remote_watcher Scanning remote child: RemoteFileInfo(name=u'Nuxeo Drive Test Workspace', uid=u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', parent_uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', folderish=True, last_modification_time=datetime.datetime(2015, 11, 20, 10, 22, 38), last_contributor=u'nuxeoDriveTestUser_user_2', digest=None, digest_algorithm=None, download_url=None, can_rename=True, can_delete=True, can_update=False, can_create_child=True)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,548 2976 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Nuxeo Drive Test Workspace', uid=u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', parent_uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', folderish=True, last_modification_time=datetime.datetime(2015, 11, 20, 10, 22, 38), last_contributor=u'nuxeoDriveTestUser_user_2', digest=None, digest_algorithm=None, download_url=None, can_rename=True, can_delete=True, can_update=False, can_create_child=True)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,551 2976 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,551 2976 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace, remote_name=None, version=0] with version=1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,555 2976 DEBUG nxdrive.engine.dao.sqlite Queuing 3 children of 'StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: None, Local state: synchronized, Remote state: synchronized, State: unsynchronized)'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,556 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,556 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:0, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,556 2976 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,556 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,559 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:0, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,559 2976 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 3
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,559 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,559 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:1, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,559 2976 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,561 2976 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,562 2976 DEBUG nxdrive.engine.dao.sqlite Queuing 3 children of 'StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: None, Local state: synchronized, Remote state: synchronized, State: unsynchronized)'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,563 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,563 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:0, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,563 2976 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 4
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,563 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,565 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:0, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,565 2976 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 5
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,565 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,565 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:1, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,565 2976 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,566 2976 DEBUG nxdrive.engine.watcher.remote_watcher Remote scanning: /Nuxeo Drive Test Workspace
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,566 2976 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,566 2976 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,631 2976 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,638 2976 DEBUG nxdrive.engine.watcher.remote_watcher Remote scan finished in 293ms
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,638 2992 DEBUG nxdrive.tests.common_unit_test Remote scan completed for engine 3d7f1ea18f6811e59cf80800279ce356
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,638 2992 TRACE nxdrive.engine.queue_manager Init processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,638 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,638 2992 DEBUG nxdrive.engine.queue_manager creating local folder processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,638 2992 DEBUG nxdrive.engine.queue_manager creating local file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,641 1332 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(1332) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,641 528 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(528) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,642 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,651 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,653 2224 DEBUG nxdrive.engine.workers Thread GenericProcessor(2224) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,654 1332 TRACE nxdrive.engine.dao.sqlite Acquired processor 1332 for row 6
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,653 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,654 1192 DEBUG nxdrive.engine.workers Thread GenericProcessor(1192) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,671 1332 DEBUG nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,673 2396 DEBUG nxdrive.engine.workers Thread GenericProcessor(2396) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,677 1332 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B2DF0>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,678 1332 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,678 528 TRACE nxdrive.engine.dao.sqlite Acquired processor 528 for row 7
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,690 528 DEBUG nxdrive.engine.processor Executing processor on StateRow[7](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,690 1332 DEBUG nxdrive.engine.processor Creating remote folder 'Original Folder 2' in folder 'Nuxeo Drive Test Workspace'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,694 1332 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'name': u'Original Folder 2', 'parentId': u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,694 528 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B2E90>> on doc pair StateRow[7](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,697 1332 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"name": "Original Folder 2", "parentId": "defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,698 528 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,700 2224 TRACE nxdrive.engine.dao.sqlite Acquired processor 2224 for row 3
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,710 2224 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,710 2224 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B2F30>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,713 1192 TRACE nxdrive.engine.dao.sqlite Acquired processor 1192 for row 4
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,714 2224 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original File 1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,721 2396 TRACE nxdrive.engine.dao.sqlite Acquired processor 2396 for row 3
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,724 2396 DEBUG nxdrive.engine.processor Executing processor on None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,726 528 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt, remote_name=None, version=1] with version=1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,729 2396 TRACE nxdrive.engine.processor Skip as pair is None or in non-processable state: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,730 1192 DEBUG nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,733 2224 DEBUG nxdrive.engine.processor Creating remote document 'Original File 1.txt' in folder 'Nuxeo Drive Test Workspace'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,736 1192 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0DA0B030>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,740 528 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B2E90>> on doc pair StateRow[7](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,740 1192 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original File 2.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,743 2396 TRACE nxdrive.engine.dao.sqlite Released processor 2396
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,743 528 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1/original file 1.1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,750 2396 TRACE nxdrive.engine.dao.sqlite Acquired processor 2396 for row 4
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,753 2396 DEBUG nxdrive.engine.processor Executing processor on None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,755 528 TRACE nxdrive.engine.dao.sqlite Released processor 528
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,756 2396 TRACE nxdrive.engine.processor Skip as pair is None or in non-processable state: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,757 1192 DEBUG nxdrive.engine.processor Creating remote document 'Original File 2.txt' in folder 'Nuxeo Drive Test Workspace'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,757 528 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(528) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,763 2396 TRACE nxdrive.engine.dao.sqlite Released processor 2396
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,763 2224 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-efc98906-a45b-4198-a40e-2d7384efb62b"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,766 2396 DEBUG nxdrive.engine.workers Thread GenericProcessor(2396) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,769 2224 TRACE nxdrive.utils Guessed mime type 'text/plain' for 'Original File 1.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,770 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,775 2224 TRACE nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 1048576 bytes
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,776 2224 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-efc98906-a45b-4198-a40e-2d7384efb62b/0 with headers {'Content-Length': 14L, 'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'X-File-Type': 'text/plain', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 14L, 'Cache-Control': 'no-cache', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%201.txt', 'X-Client-Version': '2.0-dev'} and cookies [] for file \\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original File 1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,778 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,785 1192 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-47c7f5f4-eeba-4a20-8df8-d8a3762487cf"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,786 1192 TRACE nxdrive.utils Guessed mime type 'text/plain' for 'Original File 2.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,786 1192 TRACE nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 1048576 bytes
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,786 1192 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-47c7f5f4-eeba-4a20-8df8-d8a3762487cf/0 with headers {'Content-Length': 14L, 'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'X-File-Type': 'text/plain', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 14L, 'Cache-Control': 'no-cache', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%202.txt', 'X-Client-Version': '2.0-dev'} and cookies [] for file \\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original File 2.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,790 2224 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-efc98906-a45b-4198-a40e-2d7384efb62b/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"14","uploadType":"normal","batchId":"batchId-efc98906-a45b-4198-a40e-2d7384efb62b"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,790 2224 TRACE nxdrive.client.base_automation_client Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of NuxeoDrive.CreateFile with file \\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original File 1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,792 2224 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,792 2224 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-efc98906-a45b-4198-a40e-2d7384efb62b/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"parentId": "defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,796 1192 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-47c7f5f4-eeba-4a20-8df8-d8a3762487cf/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"14","uploadType":"normal","batchId":"batchId-47c7f5f4-eeba-4a20-8df8-d8a3762487cf"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,796 1192 TRACE nxdrive.client.base_automation_client Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of NuxeoDrive.CreateFile with file \\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original File 2.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,796 1192 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,796 1192 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-47c7f5f4-eeba-4a20-8df8-d8a3762487cf/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"parentId": "defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,798 1332 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"name":"Original Folder 2","id":"defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","creationDate":1448011360777,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360777,"folder":true,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,802 1332 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,802 1332 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:True, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,802 1332 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,802 1332 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,802 1332 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,805 1332 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 2, remote_name=None, version=0] with version=0
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,805 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,812 1332 DEBUG nxdrive.engine.dao.sqlite Queuing 1 children of 'StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,812 1332 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,812 1332 TRACE nxdrive.engine.queue_manager Pushing QueueItem[10](Folderish:0, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,812 1332 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,812 1332 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B2DF0>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,812 1332 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,813 1332 TRACE nxdrive.engine.dao.sqlite Released processor 1332
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,813 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,815 2992 DEBUG nxdrive.engine.queue_manager creating local file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,818 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,819 2448 DEBUG nxdrive.engine.workers Thread GenericProcessor(2448) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,821 1332 TRACE nxdrive.engine.dao.sqlite Acquired processor 1332 for row 6
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,819 1788 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(1788) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,825 2448 DEBUG nxdrive.engine.workers Thread GenericProcessor(2448) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,828 1332 DEBUG nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,832 1332 TRACE nxdrive.engine.processor Skip as pair is None or in non-processable state: StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,834 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,835 1788 TRACE nxdrive.engine.dao.sqlite Acquired processor 1788 for row 10
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,835 1332 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,839 1332 TRACE nxdrive.engine.processor u'/nuxeo drive test workspace/original folder 2'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,841 1788 DEBUG nxdrive.engine.processor Executing processor on StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,842 1788 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0DA0B350>> on doc pair StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,842 1788 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,844 1332 TRACE nxdrive.engine.dao.sqlite Released processor 1332
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,845 1332 TRACE nxdrive.engine.dao.sqlite Acquired processor 1332 for row 6
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,845 1332 DEBUG nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,848 1332 TRACE nxdrive.engine.processor Skip as pair is None or in non-processable state: StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,848 1332 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,848 1332 TRACE nxdrive.engine.processor u'/nuxeo drive test workspace/original folder 2'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,851 1332 TRACE nxdrive.engine.dao.sqlite Released processor 1332
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,851 1332 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(1332) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,852 1788 DEBUG nxdrive.engine.processor Creating remote document 'Original File 3.txt' in folder 'Original Folder 2'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,864 1788 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-043c5427-e0ee-436a-8690-72950e844eaf"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,865 1788 TRACE nxdrive.utils Guessed mime type 'text/plain' for 'Original File 3.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,865 1788 TRACE nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 1048576 bytes
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,865 1788 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-043c5427-e0ee-436a-8690-72950e844eaf/0 with headers {'Content-Length': 14L, 'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'X-File-Type': 'text/plain', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 14L, 'Cache-Control': 'no-cache', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Original%20File%203.txt', 'X-Client-Version': '2.0-dev'} and cookies [] for file \\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2\Original File 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,885 1788 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-043c5427-e0ee-436a-8690-72950e844eaf/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"14","uploadType":"normal","batchId":"batchId-043c5427-e0ee-436a-8690-72950e844eaf"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,887 1788 TRACE nxdrive.client.base_automation_client Using 300 seconds [max(300, 2 * upload time=0)] as Nuxeo transaction timeout for batch execution of NuxeoDrive.CreateFile with file \\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2\Original File 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,887 1788 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,887 1788 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-043c5427-e0ee-436a-8690-72950e844eaf/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"parentId": "defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,890 1192 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-47c7f5f4-eeba-4a20-8df8-d8a3762487cf/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digest":"aa5728d0861fd3b174dc33202838ecb8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6/blobholder:0/Original%20File%202.txt","name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6","creationDate":1448011360865,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360865,"folder":false,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,894 1192 TRACE nxdrive.engine.processor Transfer speed 0 ko/s
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,900 1192 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,900 1192 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:False, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,900 1192 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,900 1192 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,907 1192 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 2.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,908 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,911 1192 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original File 2.txt, remote_name=None, version=0] with version=0
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,913 2224 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-efc98906-a45b-4198-a40e-2d7384efb62b/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6/blobholder:0/Original%20File%201.txt","name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6","creationDate":1448011360867,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360867,"folder":false,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,913 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,917 1552 DEBUG nxdrive.engine.workers Thread GenericProcessor(1552) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,918 1192 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0DA0B030>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,924 1192 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original file 2.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,926 2224 TRACE nxdrive.engine.processor Transfer speed 0 ko/s
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,930 1552 TRACE nxdrive.engine.dao.sqlite Acquired processor 1552 for row 4
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,930 1192 TRACE nxdrive.engine.dao.sqlite Released processor 1192
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,930 1192 DEBUG nxdrive.engine.workers Thread GenericProcessor(1192) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,936 2224 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,936 2224 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:False, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,936 2224 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,937 2224 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,938 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,940 2224 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,944 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,948 2224 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original File 1.txt, remote_name=None, version=0] with version=0
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,953 1552 DEBUG nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,957 1552 TRACE nxdrive.engine.processor Skip as pair is None or in non-processable state: StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,959 592 DEBUG nxdrive.engine.workers Thread GenericProcessor(592) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,961 2224 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0D7B2F30>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,966 592 DEBUG nxdrive.engine.workers Thread GenericProcessor(592) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,967 2224 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original file 1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,970 1552 TRACE nxdrive.engine.dao.sqlite Released processor 1552
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,973 2224 TRACE nxdrive.engine.dao.sqlite Released processor 2224
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,973 2224 DEBUG nxdrive.engine.workers Thread GenericProcessor(2224) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,976 1552 TRACE nxdrive.engine.dao.sqlite Acquired processor 1552 for row 3
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,976 1552 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,976 1552 TRACE nxdrive.engine.processor Skip as pair is None or in non-processable state: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,980 1552 TRACE nxdrive.engine.dao.sqlite Released processor 1552
10:22:49 [INFO] [exec] 2015-11-20 10:22:40,982 1552 DEBUG nxdrive.engine.workers Thread GenericProcessor(1552) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,003 1788 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-043c5427-e0ee-436a-8690-72950e844eaf/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digest":"180b2cbf65a05357269e12a1d1324635","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/590ed63c-8522-4f79-942d-93830a39bad3/blobholder:0/Original%20File%203.txt","name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f/defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3","creationDate":1448011360977,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360977,"folder":false,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,007 1788 TRACE nxdrive.engine.processor Transfer speed 0 ko/s
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,010 1788 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,010 1788 TRACE nxdrive.engine.queue_manager Pushing QueueItem[10](Folderish:False, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,010 1788 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,013 1788 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,015 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,017 1788 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,019 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,022 1788 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt, remote_name=None, version=0] with version=0
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,023 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,023 2012 DEBUG nxdrive.engine.workers Thread GenericProcessor(2012) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,028 1788 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0DA0B350>> on doc pair StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,030 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,030 1788 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2/original file 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,032 436 DEBUG nxdrive.engine.workers Thread GenericProcessor(436) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,035 2012 TRACE nxdrive.engine.dao.sqlite Acquired processor 2012 for row 10
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,039 436 DEBUG nxdrive.engine.workers Thread GenericProcessor(436) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,042 1788 TRACE nxdrive.engine.dao.sqlite Released processor 1788
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,042 2656 DEBUG nxdrive.engine.workers Thread GenericProcessor(2656) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,049 1788 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(1788) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,051 2656 DEBUG nxdrive.engine.workers Thread GenericProcessor(2656) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,053 2012 DEBUG nxdrive.engine.processor Executing processor on StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,059 2012 TRACE nxdrive.engine.processor Skip as pair is None or in non-processable state: StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3, Local state: synchronized, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,065 2012 TRACE nxdrive.engine.dao.sqlite Released processor 2012
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,065 2012 DEBUG nxdrive.engine.workers Thread GenericProcessor(2012) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,249 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,249 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,257 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,257 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,259 2708 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1 as marked unsynchronized
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,259 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,259 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'
10:22:49 [INFO] [exec] 2015-11-20 10:22:41,262 2708 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2 as marked unsynchronized
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,250 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,252 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,252 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,252 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,252 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,257 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,259 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,259 2708 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1 as marked unsynchronized
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,260 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,260 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,260 2708 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt as marked unsynchronized
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,263 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,263 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,263 2708 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt as marked unsynchronized
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,263 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,265 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,266 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 2 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40]
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,269 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,270 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,272 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2, remote_ref=defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f]
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,272 2708 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_modified: StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: modified, Remote state: synchronized, State: synchronized)
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,273 2708 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:True, State: locally_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,273 2708 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,273 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,273 2992 DEBUG nxdrive.engine.queue_manager creating local folder processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,276 1272 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(1272) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,279 1272 TRACE nxdrive.engine.dao.sqlite Acquired processor 1272 for row 6
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,280 1272 DEBUG nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: modified, Remote state: synchronized, State: locally_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,280 1272 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,282 1272 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,302 1272 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":true,"name":"Original Folder 2","id":"defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","creationDate":1448011360777,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360777,"folder":true,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,308 1272 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x0DA0B760>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: modified, Remote state: synchronized, State: locally_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,308 1272 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,308 1272 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 2, remote_name=Original Folder 2, version=1] with version=1
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,311 1272 DEBUG nxdrive.engine.dao.sqlite Queuing 1 children of 'StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: modified, Remote state: synchronized, State: locally_modified)'
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,311 1272 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,312 1272 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x0DA0B760>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: modified, Remote state: synchronized, State: locally_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,312 1272 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,312 1272 TRACE nxdrive.engine.dao.sqlite Released processor 1272
10:22:49 [INFO] [exec] 2015-11-20 10:22:42,312 1272 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(1272) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,239 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,243 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,246 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,246 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileDeletedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,246 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,246 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,246 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,247 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,249 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,253 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,253 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 2.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,257 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,259 664 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,273 2708 DEBUG nxdrive.engine.watcher.local_watcher Dropping watchdog event [created] as digest has not changed for /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,273 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,275 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,279 2708 DEBUG nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,279 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,279 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,279 2708 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1 as marked unsynchronized
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,279 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileDeletedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,279 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [deleted] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,280 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,280 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,282 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 3 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40]
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,286 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,288 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,289 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 2 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2, remote_ref=defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f]
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,293 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,293 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,296 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 4 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40]
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,299 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,301 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,302 2708 TRACE nxdrive.engine.dao.sqlite Increasing version to 3 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpjos9ef-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2, remote_ref=defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f]
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,305 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 2.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,305 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 2.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,311 2708 DEBUG nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original File 2.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,311 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,311 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,313 2708 DEBUG nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original File 1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,313 2708 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,313 2708 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpjos9ef-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,316 2708 DEBUG nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,921 2976 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,923 2976 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 1301, 'lastSyncActiveRootDefinitions': u'default:70bfb84f-acab-40e5-8a6a-698a8e55ea40'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,923 2976 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 1301, "lastSyncActiveRootDefinitions": "default:70bfb84f-acab-40e5-8a6a-698a8e55ea40"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,967 2976 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"fileSystemChanges":[{"fileSystemItem":{"digest":"180b2cbf65a05357269e12a1d1324635","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/590ed63c-8522-4f79-942d-93830a39bad3/blobholder:0/Original%20File%203.txt","name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f/defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3","creationDate":1448011360977,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360977,"folder":false,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3","fileSystemItemName":"Original File 3.txt","eventId":"documentCreated","repositoryId":"default","docUuid":"590ed63c-8522-4f79-942d-93830a39bad3","eventDate":1448011360977},{"fileSystemItem":{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6/blobholder:0/Original%20File%201.txt","name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6","creationDate":1448011360867,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360867,"folder":false,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40","canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6","fileSystemItemName":"Original File 1.txt","eventId":"documentCreated","repositoryId":"default","docUuid":"b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6","eventDate":1448011360867},{"fileSystemItem":{"digest":"aa5728d0861fd3b174dc33202838ecb8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6/blobholder:0/Original%20File%202.txt","name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6","creationDate":1448011360865,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360865,"folder":false,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40","canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6","fileSystemItemName":"Original File 2.txt","eventId":"documentCreated","repositoryId":"default","docUuid":"b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6","eventDate":1448011360865},{"fileSystemItem":{"canCreateChild":true,"name":"Original Folder 2","id":"defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","creationDate":1448011360777,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360777,"folder":true,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40","canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","fileSystemItemName":"Original Folder 2","eventId":"documentCreated","repositoryId":"default","docUuid":"13aa6a52-6fdf-4127-8af4-0a96808e0d9f","eventDate":1448011360777}],"upperBound":1327,"syncDate":1448011363000,"activeSynchronizationRootDefinitions":"default:70bfb84f-acab-40e5-8a6a-698a8e55ea40"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,969 2976 DEBUG nxdrive.engine.watcher.remote_watcher 4 remote changes detected
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,970 2976 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,970 2976 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,970 2992 DEBUG nxdrive.tests.common_unit_test Remote changes slot for: 3d7f1ea18f6811e59cf80800279ce356
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,973 2976 TRACE nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'canUpdate': True, u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'Original File 3.txt', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'digestAlgorithm': u'MD5', u'lastModificationDate': 1448011360977L, u'canRename': True, u'downloadURL': u'nxfile/default/590ed63c-8522-4f79-942d-93830a39bad3/blobholder:0/Original%20File%203.txt', u'parentId': u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f/defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3', u'folder': False, u'creationDate': 1448011360977L, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'id': u'defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3', u'digest': u'180b2cbf65a05357269e12a1d1324635'}, u'repositoryId': u'default', u'fileSystemItemName': u'Original File 3.txt', u'fileSystemItemId': u'defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3', u'docUuid': u'590ed63c-8522-4f79-942d-93830a39bad3', u'eventDate': 1448011360977L}
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,976 2976 DEBUG nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt' (force_recursion:0)
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,976 2976 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Original File 3.txt', uid=u'defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3', parent_uid=u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f/defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 10, 22, 40), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'180b2cbf65a05357269e12a1d1324635', digest_algorithm=u'md5', download_url=u'nxfile/default/590ed63c-8522-4f79-942d-93830a39bad3/blobholder:0/Original%20File%203.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,979 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,979 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[10](Folderish:False, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,979 2976 TRACE nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,980 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,980 2992 DEBUG nxdrive.engine.queue_manager creating remote file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,980 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,982 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,983 2296 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2296) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,984 2500 DEBUG nxdrive.engine.workers Thread GenericProcessor(2500) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,992 2976 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,996 2500 DEBUG nxdrive.engine.workers Thread GenericProcessor(2500) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:43,997 2976 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,003 2296 TRACE nxdrive.engine.dao.sqlite Acquired processor 2296 for row 10
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,003 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,006 2976 TRACE nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'canUpdate': True, u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'Original File 1.txt', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'digestAlgorithm': u'MD5', u'lastModificationDate': 1448011360867L, u'canRename': True, u'downloadURL': u'nxfile/default/b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6/blobholder:0/Original%20File%201.txt', u'parentId': u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6', u'folder': False, u'creationDate': 1448011360867L, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'id': u'defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6', u'digest': u'f3b09f7a82f6ac8c6077a1ca1d3778d8'}, u'repositoryId': u'default', u'fileSystemItemName': u'Original File 1.txt', u'fileSystemItemId': u'defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6', u'docUuid': u'b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6', u'eventDate': 1448011360867L}
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,005 2148 DEBUG nxdrive.engine.workers Thread GenericProcessor(2148) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,013 2148 DEBUG nxdrive.engine.workers Thread GenericProcessor(2148) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,020 1780 DEBUG nxdrive.engine.workers Thread GenericProcessor(1780) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,032 1780 DEBUG nxdrive.engine.workers Thread GenericProcessor(1780) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,032 2296 DEBUG nxdrive.engine.processor Executing processor on StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,032 2976 DEBUG nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Original File 1.txt' (force_recursion:0)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,046 2296 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0DA0B6C0>> on doc pair StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,046 2976 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Original File 1.txt', uid=u'defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6', parent_uid=u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 10, 22, 40), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f3b09f7a82f6ac8c6077a1ca1d3778d8', digest_algorithm=u'md5', download_url=u'nxfile/default/b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6/blobholder:0/Original%20File%201.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,052 2296 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,056 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,056 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:False, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,056 2976 TRACE nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,059 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,062 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,068 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,068 780 DEBUG nxdrive.engine.workers Thread GenericProcessor(780) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,069 2720 DEBUG nxdrive.engine.workers Thread GenericProcessor(2720) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,068 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,076 2720 DEBUG nxdrive.engine.workers Thread GenericProcessor(2720) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,084 2296 DEBUG nxdrive.engine.processor No local impact of metadata update on document 'Original File 3.txt'.
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,086 1276 DEBUG nxdrive.engine.workers Thread GenericProcessor(1276) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,094 2296 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt, remote_name=Original File 3.txt, version=1] with version=1
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,092 1276 DEBUG nxdrive.engine.workers Thread GenericProcessor(1276) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,098 780 TRACE nxdrive.engine.dao.sqlite Acquired processor 780 for row 3
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,102 780 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,102 780 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0DA0B490>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,104 780 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original File 1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,105 2976 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,109 2976 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,111 2976 TRACE nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'canUpdate': True, u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'Original File 2.txt', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'digestAlgorithm': u'MD5', u'lastModificationDate': 1448011360865L, u'canRename': True, u'downloadURL': u'nxfile/default/b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6/blobholder:0/Original%20File%202.txt', u'parentId': u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6', u'folder': False, u'creationDate': 1448011360865L, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'id': u'defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6', u'digest': u'aa5728d0861fd3b174dc33202838ecb8'}, u'repositoryId': u'default', u'fileSystemItemName': u'Original File 2.txt', u'fileSystemItemId': u'defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6', u'docUuid': u'b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6', u'eventDate': 1448011360865L}
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,121 2296 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0DA0B6C0>> on doc pair StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,125 2296 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2/original file 3.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,132 2296 TRACE nxdrive.engine.dao.sqlite Released processor 2296
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,135 2976 DEBUG nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Original File 2.txt' (force_recursion:0)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,135 780 DEBUG nxdrive.engine.processor No local impact of metadata update on document 'Original File 1.txt'.
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,137 2296 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2296) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,142 2976 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Original File 2.txt', uid=u'defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6', parent_uid=u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 10, 22, 40), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'aa5728d0861fd3b174dc33202838ecb8', digest_algorithm=u'md5', download_url=u'nxfile/default/b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6/blobholder:0/Original%20File%202.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,144 780 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original File 1.txt, remote_name=Original File 1.txt, version=1] with version=1
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,151 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,151 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:False, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,153 2976 TRACE nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,154 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,155 2992 DEBUG nxdrive.engine.queue_manager creating remote file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,157 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,158 780 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0DA0B490>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#b8595ee1-bdfc-4fdb-90ac-5d6d06a1bfd6, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,157 2580 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2580) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,158 3032 DEBUG nxdrive.engine.workers Thread GenericProcessor(3032) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,157 2992 DEBUG nxdrive.engine.queue_manager creating additional file processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,165 780 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original file 1.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,173 3032 DEBUG nxdrive.engine.workers Thread GenericProcessor(3032) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,178 2192 DEBUG nxdrive.engine.workers Thread GenericProcessor(2192) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,180 2580 TRACE nxdrive.engine.dao.sqlite Acquired processor 2580 for row 4
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,181 2192 DEBUG nxdrive.engine.workers Thread GenericProcessor(2192) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,186 780 TRACE nxdrive.engine.dao.sqlite Released processor 780
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,191 780 DEBUG nxdrive.engine.workers Thread GenericProcessor(780) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,197 2580 DEBUG nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,200 2580 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0DA0BBC0>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,200 2976 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,203 2580 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original File 2.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,203 2976 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,206 2976 TRACE nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'Original Folder 2', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'lastModificationDate': 1448011360777L, u'canRename': True, u'canCreateChild': True, u'parentId': u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f', u'folder': True, u'creationDate': 1448011360777L, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'id': u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f'}, u'repositoryId': u'default', u'fileSystemItemName': u'Original Folder 2', u'fileSystemItemId': u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f', u'docUuid': u'13aa6a52-6fdf-4127-8af4-0a96808e0d9f', u'eventDate': 1448011360777L}
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,210 2976 DEBUG nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Original Folder 2' (force_recursion:0)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,214 2976 TRACE nxdrive.engine.dao.sqlite Increasing version to 4 for pair RemoteFileInfo(name=u'Original Folder 2', uid=u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f', parent_uid=u'defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f', folderish=True, last_modification_time=datetime.datetime(2015, 11, 20, 10, 22, 40), last_contributor=u'nuxeoDriveTestUser_user_1', digest=None, digest_algorithm=None, download_url=None, can_rename=True, can_delete=True, can_update=False, can_create_child=True)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,217 2580 DEBUG nxdrive.engine.processor No local impact of metadata update on document 'Original File 2.txt'.
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,219 2580 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original File 2.txt, remote_name=Original File 2.txt, version=1] with version=1
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,220 2976 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,220 2976 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:True, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,220 2976 TRACE nxdrive.engine.queue_manager Pushed to _remote_folder_queue, now of size: 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,221 2992 TRACE nxdrive.engine.queue_manager Launching processors
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,223 2992 DEBUG nxdrive.engine.queue_manager creating remote folder processor
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,223 2824 DEBUG nxdrive.engine.workers Thread RemoteFolderProcessor(2824) start
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,224 2580 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0DA0BBC0>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: defaultFileSystemItemFactory#default#b5e0cc4a-8ad3-45f7-a065-72bf1a534ef6, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,227 2580 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original file 2.txt
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,230 2976 DEBUG nxdrive.engine.watcher.remote_watcher Remote scanning: /Nuxeo Drive Test Workspace/Original Folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,232 2976 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,232 2976 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"id": "defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,233 2824 TRACE nxdrive.engine.dao.sqlite Acquired processor 2824 for row 6
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,236 2580 TRACE nxdrive.engine.dao.sqlite Released processor 2580
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,236 2824 DEBUG nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,240 2580 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2580) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,243 2824 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0DA0BDA0>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,244 2824 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,246 2824 DEBUG nxdrive.engine.processor No local impact of metadata update on document 'Original Folder 2'.
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,246 2824 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 2, remote_name=Original Folder 2, version=4] with version=4
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,250 2824 DEBUG nxdrive.engine.dao.sqlite Queuing 1 children of 'StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: synchronized, Remote state: modified, State: remotely_modified)'
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,252 2824 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,252 2824 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0DA0BDA0>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f, Local state: synchronized, Remote state: modified, State: remotely_modified)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,253 2824 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,253 2824 TRACE nxdrive.engine.dao.sqlite Released processor 2824
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,253 2824 DEBUG nxdrive.engine.workers Thread RemoteFolderProcessor(2824) end
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,299 2976 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digest":"180b2cbf65a05357269e12a1d1324635","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/590ed63c-8522-4f79-942d-93830a39bad3/blobholder:0/Original%20File%203.txt","name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f/defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3","creationDate":1448011360977,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448011360977,"folder":false,"creator":"nuxeoDriveTestUser_user_1","canDelete":true,"parentId":"defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f","canRename":true,"userName":"nuxeoDriveTestUser_user_1"}]'
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,299 2976 TRACE nxdrive.engine.watcher.remote_watcher Scanning remote child: RemoteFileInfo(name=u'Original File 3.txt', uid=u'defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3', parent_uid=u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f/defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 10, 22, 40), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'180b2cbf65a05357269e12a1d1324635', digest_algorithm=u'md5', download_url=u'nxfile/default/590ed63c-8522-4f79-942d-93830a39bad3/blobholder:0/Original%20File%203.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,301 2976 TRACE nxdrive.engine.dao.sqlite Increasing version to 2 for pair RemoteFileInfo(name=u'Original File 3.txt', uid=u'defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3', parent_uid=u'defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#70bfb84f-acab-40e5-8a6a-698a8e55ea40/defaultFileSystemItemFactory#default#13aa6a52-6fdf-4127-8af4-0a96808e0d9f/defaultFileSystemItemFactory#default#590ed63c-8522-4f79-942d-93830a39bad3', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 10, 22, 40), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'180b2cbf65a05357269e12a1d1324635', digest_algorithm=u'md5', download_url=u'nxfile/default/590ed63c-8522-4f79-942d-93830a39bad3/blobholder:0/Original%20File%203.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,302 2976 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
10:22:49 [INFO] [exec] 2015-11-20 10:22:44,312 2992 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 0
10:22:49 [INFO] [exec] 2015-11-20 10:22:47,562 2976 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
10:22:49 [INFO] [exec] 2015-11-20 10:22:47,563 2976 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 1327, 'lastSyncActiveRootDefinitions': u'default:70bfb84f-acab-40e5-8a6a-698a8e55ea40'}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:47,565 2976 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '8bf50e2f-92a1-4d1b-a9e7-83ecb0ecd995', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '3d65a3308f6811e5bd650800279ce356', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"lowerBound": 1327, "lastSyncActiveRootDefinitions": "default:70bfb84f-acab-40e5-8a6a-698a8e55ea40"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:47,589 2976 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"fileSystemChanges":[],"upperBound":1331,"syncDate":1448011367000,"activeSynchronizationRootDefinitions":"default:70bfb84f-acab-40e5-8a6a-698a8e55ea40"}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:47,591 2992 TRACE nxdrive.tests.common_unit_test No remote changes slot for: 3d7f1ea18f6811e59cf80800279ce356
10:22:49 [INFO] [exec] 2015-11-20 10:22:47,599 2992 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
10:22:49 [INFO] [exec] 2015-11-20 10:22:47,601 2992 DEBUG nxdrive.engine.engine Emitting syncCompleted for engine 3d7f1ea18f6811e59cf80800279ce356
10:22:49 [INFO] [exec] 2015-11-20 10:22:47,602 2992 DEBUG nxdrive.tests.common_unit_test Sync Completed slot for: 3d7f1ea18f6811e59cf80800279ce356
10:22:49 [INFO] [exec] 2015-11-20 10:22:48,253 1684 DEBUG nxdrive.tests.common_unit_test Sync completed, ended wait for sync
10:22:49 [INFO] [exec] 2015-11-20 10:22:48,253 1684 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'query': u"SELECT * FROM Document WHERE ecm:path = '/default-domain/workspaces/nuxeo-drive-test-workspace/Original Folder 1' AND ecm:currentLifeCycleState != 'deleted' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}
10:22:49 [INFO] [exec] 2015-11-20 10:22:48,253 1684 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/Document.Query with headers {'X-Client-Version': '2.0-dev', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': u'nxdrive-test-device-1', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'X-Application-Name': 'Nuxeo Drive', 'Authorization': 'Basic bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTplMmM2ZTU='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:path = \'/default-domain/workspaces/nuxeo-drive-test-workspace/Original Folder 1\' AND ecm:currentLifeCycleState != \'deleted\' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}'
10:22:49 [INFO] [exec] 2015-11-20 10:22:48,322 1684 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Query' with cookies []: '{"entity-type":"documents","isPaginable":true,"resultsCount":0,"pageSize":0,"maxPageSize":1000,"currentPageSize":0,"currentPageIndex":0,"numberOfPages":1,"isPreviousPageAvailable":false,"isNextPageAvailable":false,"isLastPageAvailable":false,"isSortable":true,"hasError":false,"errorMessage":null,"totalSize":0,"pageIndex":0,"pageCount":1,"entries":[]}'
10:22:49 [INFO] [exec] --------------------- >> end captured logging << ---------------------
