11:28:27 [INFO] [exec] ======================================================================
11:28:27 [INFO] [exec] FAIL: test_local_move_and_rename_file (nxdrive.tests.test_local_move_and_rename.TestLocalMoveAndRename)
11:28:27 [INFO] [exec] ----------------------------------------------------------------------
11:28:27 [INFO] [exec] Traceback (most recent call last):
11:28:27 [INFO] [exec] File "C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\nuxeo-drive-client\nxdrive\tests\test_local_move_and_rename.py", line 232, in test_local_move_and_rename_file
11:28:27 [INFO] [exec] u'/Original Folder 1/Renamed File 1 \xe9.txt'))
11:28:27 [INFO] [exec] AssertionError: False is not true
11:28:27 [INFO] [exec] -------------------- >> begin captured logging << --------------------
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,730 2736 DEBUG nxdrive.engine.dao.sqlite Create DAO on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\nuxeo-drive-conf\manager.db
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,732 2736 DEBUG nxdrive.engine.dao.sqlite Create main connexion on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\nuxeo-drive-conf\manager.db (dir exists: 1 / file exists: 0)
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,747 2736 DEBUG nxdrive.osi Using Windows OS integration
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,752 2736 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/
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,756 2736 DEBUG nxdrive.engine.dao.sqlite Create DAO on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmp4wkmdv-nxdrive-tests-user-2\nuxeo-drive-conf\manager.db
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,756 2736 DEBUG nxdrive.engine.dao.sqlite Create main connexion on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmp4wkmdv-nxdrive-tests-user-2\nuxeo-drive-conf\manager.db (dir exists: 1 / file exists: 0)
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,772 2736 DEBUG nxdrive.osi Using Windows OS integration
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,775 2736 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/
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,778 2736 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,779 2736 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 []
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,812 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,812 2736 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": "/"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,825 2736 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"e6d1cc2e-151c-4aff-a9df-feedea7ed24b","path":"/","type":"Root","state":null,"parentRef":"/","isCheckedOut":true,"changeToken":null,"title":"e6d1cc2e-151c-4aff-a9df-feedea7ed24b","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"]}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,825 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,825 2736 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"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,908 2736 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'
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,915 2736 DEBUG nxdrive.engine.dao.sqlite Create DAO on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\nuxeo-drive-conf\ndrive_6559d2918f7111e59415080027915b3f.db
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,915 2736 DEBUG nxdrive.engine.dao.sqlite Create main connexion on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\nuxeo-drive-conf\ndrive_6559d2918f7111e59415080027915b3f.db (dir exists: 1 / file exists: 0)
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,928 2736 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,931 2736 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite finished
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,934 2736 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,934 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTozODQxNTg='} and cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,960 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Windows+Desktop&revoke=false&deviceId=6540cc518f7111e5ba03080027915b3f&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTozODQxNTg='} and cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,970 2736 TRACE nxdrive.client.base_automation_client Got token '8820f858-5a2b-475e-ac71-ad246170ce07' with cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,982 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,982 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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": {}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,993 2736 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/"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:09,993 2736 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/'}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,003 2736 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,003 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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 []
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,032 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,032 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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": {}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,042 2736 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#","folder":true,"creationDate":39,"lastModificationDate":39,"lastContributor":"system","creator":"system","parentId":null,"canDelete":false,"canRename":false,"userName":"nuxeoDriveTestUser_user_1"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,042 2736 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,048 2736 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,048 2736 TRACE nxdrive.client.local_client Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_1|6540cc518f7111e5ba03080027915b3f|6559d2918f7111e59415080027915b3f' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,049 2736 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,052 2736 DEBUG nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[1](Local: u'/', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,058 2736 DEBUG nxdrive.engine.watcher.local_watcher Windows detected so delete event will be delayed by 2000ms
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,062 2736 DEBUG nxdrive.engine.dao.sqlite Create DAO on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmp4wkmdv-nxdrive-tests-user-2\nuxeo-drive-conf\ndrive_657040c08f7111e5959b080027915b3f.db
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,062 2736 DEBUG nxdrive.engine.dao.sqlite Create main connexion on C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmp4wkmdv-nxdrive-tests-user-2\nuxeo-drive-conf\ndrive_657040c08f7111e5959b080027915b3f.db (dir exists: 1 / file exists: 0)
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,075 2736 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,079 2736 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite finished
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,081 2736 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,081 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '654475cf8f7111e58e5b080027915b3f', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiMDFkNzg='} and cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,117 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Windows+Desktop&revoke=false&deviceId=654475cf8f7111e58e5b080027915b3f&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '654475cf8f7111e58e5b080027915b3f', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiMDFkNzg='} and cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,127 2736 TRACE nxdrive.client.base_automation_client Got token '8e823ae0-3a39-4377-97e3-6d8790d67507' with cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,138 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,138 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '8e823ae0-3a39-4377-97e3-6d8790d67507', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '654475cf8f7111e58e5b080027915b3f', '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": {}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,147 2736 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/"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,147 2736 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/'}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,155 2736 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,155 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '8e823ae0-3a39-4377-97e3-6d8790d67507', 'X-Device-Id': '654475cf8f7111e58e5b080027915b3f', '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 []
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,180 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,180 2736 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '8e823ae0-3a39-4377-97e3-6d8790d67507', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '654475cf8f7111e58e5b080027915b3f', '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": {}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,190 2736 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#","folder":true,"creationDate":187,"lastModificationDate":187,"lastContributor":"system","creator":"system","parentId":null,"canDelete":false,"canRename":false,"userName":"nuxeoDriveTestUser_user_2"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,190 2736 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,196 2736 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,196 2736 TRACE nxdrive.client.local_client Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_2|654475cf8f7111e58e5b080027915b3f|657040c08f7111e5959b080027915b3f' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmp4wkmdv-nxdrive-tests-user-2\\Nuxeo Drive'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,197 2736 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,198 2736 DEBUG nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[1](Local: u'/', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,203 2736 DEBUG nxdrive.engine.watcher.local_watcher Windows detected so delete event will be delayed by 2000ms
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,204 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,206 2736 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"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,221 2736 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"ea414d64-7c4d-4675-825a-1b1eb195c538","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"1491093d-59ef-4f2e-82ae-9247719a1dc2","isCheckedOut":true,"changeToken":"1448015289850","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-20T10:28:09.85Z","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-20T10:28:09.85Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-20T10:28:09.85Z","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"]}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,224 2736 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,224 2736 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTozODQxNTg='} and cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,246 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,246 2736 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTozODQxNTg='}, cookies [] and JSON payload '{"params": {"value": "ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,256 2736 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"ea414d64-7c4d-4675-825a-1b1eb195c538","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"1491093d-59ef-4f2e-82ae-9247719a1dc2","isCheckedOut":true,"changeToken":"1448015289850","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-20T10:28:09.85Z","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-20T10:28:09.85Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-20T10:28:09.85Z","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"]}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,257 2736 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,257 2736 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiMDFkNzg='} and cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,289 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,289 2736 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiMDFkNzg='}, cookies [] and JSON payload '{"params": {"value": "ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,299 2736 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"ea414d64-7c4d-4675-825a-1b1eb195c538","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"1491093d-59ef-4f2e-82ae-9247719a1dc2","isCheckedOut":true,"changeToken":"1448015289850","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-20T10:28:09.85Z","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-20T10:28:09.85Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-20T10:28:09.85Z","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"]}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,301 2736 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,301 2736 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTozODQxNTg='} and cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,328 2736 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,328 2736 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiMDFkNzg='} and cookies []
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,358 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'input': u'doc:ea414d64-7c4d-4675-825a-1b1eb195c538', 'params': {'enable': True}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,358 2736 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTozODQxNTg='}, cookies [] and JSON payload '{"input": "doc:ea414d64-7c4d-4675-825a-1b1eb195c538", "params": {"enable": true}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,437 2736 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,437 2736 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'input': u'doc:ea414d64-7c4d-4675-825a-1b1eb195c538', 'params': {'enable': True}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,437 2736 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpiMDFkNzg='}, cookies [] and JSON payload '{"input": "doc:ea414d64-7c4d-4675-825a-1b1eb195c538", "params": {"enable": true}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,520 2736 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
11:28:27 [INFO] [exec] 2015-11-20 11:28:10,523 2468 DEBUG nxdrive.tests.common_unit_test UnitTest thread started
11:28:27 [INFO] [exec] 2015-11-20 11:28:11,526 2468 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\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive'
11:28:27 [INFO] [exec] 2015-11-20 11:28:11,529 2468 TRACE nxdrive.client.local_client Removing xattr drive-fs-test from \\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive
11:28:27 [INFO] [exec] 2015-11-20 11:28:11,530 2468 DEBUG nxdrive.engine.engine Engine start
11:28:27 [INFO] [exec] 2015-11-20 11:28:11,532 2968 DEBUG nxdrive.engine.workers Thread LocalWatcher(2968) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:11,535 2968 DEBUG nxdrive.engine.watcher.local_watcher Watching FS modification on : C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive
11:28:27 [INFO] [exec] 2015-11-20 11:28:11,546 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:11,549 2468 DEBUG nxdrive.tests.common_unit_test Wait for sync
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,549 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,556 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,563 2968 DEBUG nxdrive.engine.watcher.local_watcher Watchdog setup finished
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,565 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,569 2968 DEBUG nxdrive.engine.watcher.local_watcher Full scan started
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,572 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,575 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,579 1600 TRACE nxdrive.engine.watcher.local_watcher DriveFSROOT: Nuxeo Drive : need: Nuxeo Drive
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,584 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,589 2968 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,591 2968 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,591 2968 TRACE nxdrive.engine.queue_manager Pushing QueueItem[2](Folderish:True, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,591 2968 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,596 2968 DEBUG nxdrive.engine.watcher.local_watcher Found new file /Nuxeo Drive Test Workspace/Original File 1.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,601 2968 DEBUG nxdrive.engine.watcher.local_watcher Found new file /Nuxeo Drive Test Workspace/Original File 2.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,605 2968 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace/Original Folder 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,608 2968 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace/Original Folder 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,611 2968 DEBUG nxdrive.engine.watcher.local_watcher Found new file /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,615 2968 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,617 2968 DEBUG nxdrive.engine.watcher.local_watcher Found new folder /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,621 2968 DEBUG nxdrive.engine.watcher.local_watcher Found new file /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,627 2968 DEBUG nxdrive.engine.watcher.local_watcher Full scan finished in 54ms
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,628 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,628 300 DEBUG nxdrive.engine.workers Thread RemoteWatcher(300) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,631 2736 DEBUG nxdrive.engine.queue_manager creating local folder processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,632 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,634 2804 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(2804) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,638 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,638 300 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=True
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,641 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,644 300 DEBUG nxdrive.engine.watcher.remote_watcher Remote full scan
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,645 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,650 2804 TRACE nxdrive.engine.dao.sqlite Acquired processor 2804 for row 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,657 300 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,663 300 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,670 2804 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,678 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1, remote_ref=None]
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,678 2804 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86490>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,683 2804 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,684 2968 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,687 2968 TRACE nxdrive.engine.queue_manager Pushing QueueItem[5](Folderish:True, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,690 300 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#","folder":true,"creationDate":681,"lastModificationDate":681,"lastContributor":"system","creator":"system","parentId":null,"canDelete":false,"canRename":false,"userName":"nuxeoDriveTestUser_user_1"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,691 2968 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,694 300 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,697 2804 WARNING nxdrive.engine.processor Won't synchronize folder 'Nuxeo Drive Test Workspace' created in local folder '' since it is readonly
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,698 2804 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,698 2804 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace, remote_name=None, version=0] with version=0
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,704 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,706 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,707 300 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,710 300 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,713 300 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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": {}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,717 2804 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86490>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,721 2804 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,721 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1\Sub-Folder 1.1, remote_ref=None]
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,726 2804 TRACE nxdrive.engine.dao.sqlite Released processor 2804
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,729 2968 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,729 2968 TRACE nxdrive.engine.queue_manager Pushing QueueItem[8](Folderish:True, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,729 2968 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,732 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,733 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,736 2804 TRACE nxdrive.engine.dao.sqlite Acquired processor 2804 for row 5
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,736 2804 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,737 2804 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86490>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,737 2804 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,743 2804 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
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,743 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1\Sub-Folder 1.2, remote_ref=None]
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,747 2804 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86490>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,750 2804 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,750 2968 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,753 2968 TRACE nxdrive.engine.queue_manager Pushing QueueItem[9](Folderish:True, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,753 2968 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,756 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,757 2804 TRACE nxdrive.engine.dao.sqlite Released processor 2804
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,757 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,762 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1\Original File 1.1.txt, remote_ref=None]
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,765 2804 TRACE nxdrive.engine.dao.sqlite Acquired processor 2804 for row 8
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,766 2968 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,766 2804 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,769 2968 TRACE nxdrive.engine.queue_manager Pushing QueueItem[7](Folderish:False, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,772 2804 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86490>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,772 2968 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,773 2804 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,779 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,780 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,785 2804 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
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,786 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,788 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,790 2804 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86490>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,792 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'>
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,793 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.1'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,792 2804 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1/sub-folder 1.1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,802 2804 TRACE nxdrive.engine.dao.sqlite Released processor 2804
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,803 300 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"fileSystemChanges":[],"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:ea414d64-7c4d-4675-825a-1b1eb195c538","upperBound":1525,"syncDate":1448015292000}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,805 2968 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.1 as marked unsynchronized
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,808 2804 TRACE nxdrive.engine.dao.sqlite Acquired processor 2804 for row 9
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,808 2804 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,809 2804 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86490>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,809 2804 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,812 300 DEBUG nxdrive.engine.watcher.remote_watcher Remote scanning: /
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,812 300 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,812 300 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,815 2804 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
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,818 2804 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86490>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,819 2804 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1/sub-folder 1.2
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,819 2804 TRACE nxdrive.engine.dao.sqlite Released processor 2804
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,819 2804 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(2804) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,826 300 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#ea414d64-7c4d-4675-825a-1b1eb195c538","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","folder":true,"creationDate":1448015289850,"lastModificationDate":1448015290504,"lastContributor":"nuxeoDriveTestUser_user_2","creator":"Administrator","parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"}]'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,828 300 TRACE nxdrive.engine.watcher.remote_watcher Scanning remote child: RemoteFileInfo(name=u'Nuxeo Drive Test Workspace', uid=u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', parent_uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', folderish=True, last_modification_time=datetime.datetime(2015, 11, 20, 11, 28, 10), 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,828 300 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Nuxeo Drive Test Workspace', uid=u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', parent_uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', folderish=True, last_modification_time=datetime.datetime(2015, 11, 20, 11, 28, 10), 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,831 300 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,831 300 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace, remote_name=None, version=0] with version=1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,832 300 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)'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,832 300 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,832 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:0, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,832 300 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,834 300 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,835 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:0, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,835 300 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 3
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,835 300 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,835 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:1, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,835 300 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,836 300 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,838 300 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)'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,838 300 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,838 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:0, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,838 300 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 4
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,838 300 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,839 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:0, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,839 300 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 5
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,841 300 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,842 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:1, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,842 300 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,842 300 DEBUG nxdrive.engine.watcher.remote_watcher Remote scanning: /Nuxeo Drive Test Workspace
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,842 300 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,842 300 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,904 300 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,914 300 DEBUG nxdrive.engine.watcher.remote_watcher Remote scan finished in 262ms
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,914 2736 DEBUG nxdrive.tests.common_unit_test Remote scan completed for engine 6559d2918f7111e59415080027915b3f
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,914 2736 TRACE nxdrive.engine.queue_manager Init processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,914 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,914 2736 DEBUG nxdrive.engine.queue_manager creating local folder processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,915 2736 DEBUG nxdrive.engine.queue_manager creating local file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,915 868 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(868) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,917 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,915 2660 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(2660) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,923 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,923 1188 DEBUG nxdrive.engine.workers Thread GenericProcessor(1188) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,926 868 TRACE nxdrive.engine.dao.sqlite Acquired processor 868 for row 6
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,927 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,930 2084 DEBUG nxdrive.engine.workers Thread GenericProcessor(2084) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,943 3052 DEBUG nxdrive.engine.workers Thread GenericProcessor(3052) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,944 868 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,947 868 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86850>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,947 868 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,956 2660 TRACE nxdrive.engine.dao.sqlite Acquired processor 2660 for row 7
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,957 868 DEBUG nxdrive.engine.processor Creating remote folder 'Original Folder 2' in folder 'Nuxeo Drive Test Workspace'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,959 868 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'name': u'Original Folder 2', 'parentId': u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,959 868 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,963 1188 TRACE nxdrive.engine.dao.sqlite Acquired processor 1188 for row 3
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,967 2084 TRACE nxdrive.engine.dao.sqlite Acquired processor 2084 for row 4
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,969 3052 TRACE nxdrive.engine.dao.sqlite Acquired processor 3052 for row 3
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,970 3052 DEBUG nxdrive.engine.processor Executing processor on None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,970 3052 TRACE nxdrive.engine.processor Skip as pair is None or in non-processable state: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,970 2084 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,971 2660 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,973 3052 TRACE nxdrive.engine.dao.sqlite Released processor 3052
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,974 2084 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86A30>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,979 2660 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE868F0>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,980 2084 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original File 2.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,982 3052 TRACE nxdrive.engine.dao.sqlite Acquired processor 3052 for row 4
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,983 2660 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,982 1188 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,986 3052 DEBUG nxdrive.engine.processor Executing processor on None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,993 3052 TRACE nxdrive.engine.processor Skip as pair is None or in non-processable state: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,993 1188 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86990>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:12,997 1188 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original File 1.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,000 3052 TRACE nxdrive.engine.dao.sqlite Released processor 3052
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,003 2084 DEBUG nxdrive.engine.processor Creating remote document 'Original File 2.txt' in folder 'Nuxeo Drive Test Workspace'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,005 3052 DEBUG nxdrive.engine.workers Thread GenericProcessor(3052) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,007 2660 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
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,023 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,026 1188 DEBUG nxdrive.engine.processor Creating remote document 'Original File 1.txt' in folder 'Nuxeo Drive Test Workspace'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,032 2660 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE868F0>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,038 2660 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1/original file 1.1.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,042 2660 TRACE nxdrive.engine.dao.sqlite Released processor 2660
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,042 2660 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(2660) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,045 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,046 2084 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-c17f9ddf-51e6-4561-8e4a-42550fb05b23"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,048 2084 TRACE nxdrive.utils Guessed mime type 'text/plain' for 'Original File 2.txt'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,051 2084 TRACE nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 1048576 bytes
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,053 2084 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-c17f9ddf-51e6-4561-8e4a-42550fb05b23/0 with headers {'Content-Length': 14L, 'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original File 2.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,055 868 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#53afea78-50ee-43b0-a2ce-3b6499576069","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069","folder":true,"creationDate":1448015293030,"lastModificationDate":1448015293030,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,056 1188 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-5ae77c32-bd64-4bbe-8b2b-ca61c5087dea"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,062 1188 TRACE nxdrive.utils Guessed mime type 'text/plain' for 'Original File 1.txt'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,065 868 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,065 1188 TRACE nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 1048576 bytes
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,071 868 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:True, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,071 1188 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-5ae77c32-bd64-4bbe-8b2b-ca61c5087dea/0 with headers {'Content-Length': 14L, 'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original File 1.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,072 868 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,078 868 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,078 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,079 868 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,084 2084 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-c17f9ddf-51e6-4561-8e4a-42550fb05b23/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"14","uploadType":"normal","batchId":"batchId-c17f9ddf-51e6-4561-8e4a-42550fb05b23"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,085 868 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
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,085 2084 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\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original File 2.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,086 2084 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,086 2084 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-c17f9ddf-51e6-4561-8e4a-42550fb05b23/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,092 1188 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-5ae77c32-bd64-4bbe-8b2b-ca61c5087dea/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"14","uploadType":"normal","batchId":"batchId-5ae77c32-bd64-4bbe-8b2b-ca61c5087dea"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,092 868 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)'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,094 1188 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\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original File 1.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,094 868 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,096 1188 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,096 868 TRACE nxdrive.engine.queue_manager Pushing QueueItem[10](Folderish:0, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,098 1188 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-5ae77c32-bd64-4bbe-8b2b-ca61c5087dea/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,098 868 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,101 868 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86850>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,102 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,105 868 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,108 2736 DEBUG nxdrive.engine.queue_manager creating local file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,111 868 TRACE nxdrive.engine.dao.sqlite Released processor 868
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,112 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,117 2072 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(2072) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,118 868 TRACE nxdrive.engine.dao.sqlite Acquired processor 868 for row 6
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,119 2264 DEBUG nxdrive.engine.workers Thread GenericProcessor(2264) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,121 868 DEBUG nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,121 2264 DEBUG nxdrive.engine.workers Thread GenericProcessor(2264) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,124 2072 TRACE nxdrive.engine.dao.sqlite Acquired processor 2072 for row 10
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,125 868 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#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,127 868 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,127 868 TRACE nxdrive.engine.processor u'/nuxeo drive test workspace/original folder 2'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,131 2072 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,131 2072 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86D50>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,131 2072 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,134 868 TRACE nxdrive.engine.dao.sqlite Released processor 868
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,137 868 TRACE nxdrive.engine.dao.sqlite Acquired processor 868 for row 6
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,137 868 DEBUG nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,138 868 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#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,138 868 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,138 868 TRACE nxdrive.engine.processor u'/nuxeo drive test workspace/original folder 2'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,141 868 TRACE nxdrive.engine.dao.sqlite Released processor 868
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,141 868 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(868) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,141 2072 DEBUG nxdrive.engine.processor Creating remote document 'Original File 3.txt' in folder 'Original Folder 2'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,153 2072 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-ffb1a5da-fa12-46c6-a80a-3ca383b4c6cb"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,154 2072 TRACE nxdrive.utils Guessed mime type 'text/plain' for 'Original File 3.txt'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,154 2072 TRACE nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 1048576 bytes
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,154 2072 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-ffb1a5da-fa12-46c6-a80a-3ca383b4c6cb/0 with headers {'Content-Length': 14L, 'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2\Original File 3.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,167 2072 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-ffb1a5da-fa12-46c6-a80a-3ca383b4c6cb/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"14","uploadType":"normal","batchId":"batchId-ffb1a5da-fa12-46c6-a80a-3ca383b4c6cb"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,167 2072 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\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2\Original File 3.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,168 2072 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069'}}
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,168 2072 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-ffb1a5da-fa12-46c6-a80a-3ca383b4c6cb/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#53afea78-50ee-43b0-a2ce-3b6499576069"}}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,174 2084 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-c17f9ddf-51e6-4561-8e4a-42550fb05b23/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digest":"aa5728d0861fd3b174dc33202838ecb8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/28896da6-2d3f-40fb-9237-f4809dcd28a8/blobholder:0/Original%20File%202.txt","name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8","folder":false,"creationDate":1448015293156,"lastModificationDate":1448015293156,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,178 2084 TRACE nxdrive.engine.processor Transfer speed 0 ko/s
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,184 2084 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,184 2084 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:False, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,184 2084 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,184 2084 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,184 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,186 2084 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 2.txt'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,187 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,188 2084 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
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,188 2928 DEBUG nxdrive.engine.workers Thread GenericProcessor(2928) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,193 2084 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86A30>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,193 2084 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original file 2.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,201 1188 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-5ae77c32-bd64-4bbe-8b2b-ca61c5087dea/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060/blobholder:0/Original%20File%201.txt","name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","folder":false,"creationDate":1448015293177,"lastModificationDate":1448015293177,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,203 2928 TRACE nxdrive.engine.dao.sqlite Acquired processor 2928 for row 4
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,204 2084 TRACE nxdrive.engine.dao.sqlite Released processor 2084
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,206 2084 DEBUG nxdrive.engine.workers Thread GenericProcessor(2084) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,207 2928 DEBUG nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,209 2928 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#28896da6-2d3f-40fb-9237-f4809dcd28a8, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,213 1188 TRACE nxdrive.engine.processor Transfer speed 0 ko/s
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,216 2928 TRACE nxdrive.engine.dao.sqlite Released processor 2928
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,217 2928 DEBUG nxdrive.engine.workers Thread GenericProcessor(2928) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,221 1188 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,221 1188 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:False, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,221 1188 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,221 1188 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,223 1188 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,223 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,226 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,226 1188 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
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,230 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,233 3044 DEBUG nxdrive.engine.workers Thread GenericProcessor(3044) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,236 1188 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86990>> 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)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,240 1188 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original file 1.txt
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,243 2572 DEBUG nxdrive.engine.workers Thread GenericProcessor(2572) start
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,246 2572 DEBUG nxdrive.engine.workers Thread GenericProcessor(2572) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,246 3044 TRACE nxdrive.engine.dao.sqlite Acquired processor 3044 for row 3
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,252 1188 TRACE nxdrive.engine.dao.sqlite Released processor 1188
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,256 3044 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,257 1188 DEBUG nxdrive.engine.workers Thread GenericProcessor(1188) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,259 3044 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#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,263 3044 TRACE nxdrive.engine.dao.sqlite Released processor 3044
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,263 3044 DEBUG nxdrive.engine.workers Thread GenericProcessor(3044) end
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,275 2072 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-ffb1a5da-fa12-46c6-a80a-3ca383b4c6cb/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digest":"180b2cbf65a05357269e12a1d1324635","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/b67ab505-e798-4fa2-91f1-aa5cabe76356/blobholder:0/Original%20File%203.txt","name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069/defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356","folder":false,"creationDate":1448015293254,"lastModificationDate":1448015293254,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,280 2072 TRACE nxdrive.engine.processor Transfer speed 0 ko/s
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,285 2072 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,286 2072 TRACE nxdrive.engine.queue_manager Pushing QueueItem[10](Folderish:False, State: locally_created)
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,286 2072 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,286 2072 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,286 2072 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356' on u'\\\\?\\C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,286 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,289 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,290 2072 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
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,292 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:27 [INFO] [exec] 2015-11-20 11:28:13,293 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,296 2072 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x0EE86D50>> 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)
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,293 2184 DEBUG nxdrive.engine.workers Thread GenericProcessor(2184) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,296 2020 DEBUG nxdrive.engine.workers Thread GenericProcessor(2020) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,302 2072 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2/original file 3.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,305 2020 DEBUG nxdrive.engine.workers Thread GenericProcessor(2020) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,308 2156 DEBUG nxdrive.engine.workers Thread GenericProcessor(2156) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,311 2184 TRACE nxdrive.engine.dao.sqlite Acquired processor 2184 for row 10
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,315 2156 DEBUG nxdrive.engine.workers Thread GenericProcessor(2156) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,321 2072 TRACE nxdrive.engine.dao.sqlite Released processor 2072
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,328 2072 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(2072) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,332 2184 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#b67ab505-e798-4fa2-91f1-aa5cabe76356, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,336 2184 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#b67ab505-e798-4fa2-91f1-aa5cabe76356, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,342 2184 TRACE nxdrive.engine.dao.sqlite Released processor 2184
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,344 2184 DEBUG nxdrive.engine.workers Thread GenericProcessor(2184) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,578 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,578 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,585 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,586 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,588 2968 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1 as marked unsynchronized
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,588 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,589 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Sub-Folder 1.2'
11:28:28 [INFO] [exec] 2015-11-20 11:28:13,592 2968 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1/Sub-Folder 1.2 as marked unsynchronized
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,579 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,579 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,581 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,581 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,581 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,582 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,582 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,584 2968 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1 as marked unsynchronized
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,585 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,585 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,588 2968 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt as marked unsynchronized
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,588 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,588 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Original File 1.1.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,591 2968 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1/Original File 1.1.txt as marked unsynchronized
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,591 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,591 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,592 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 2 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538]
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,595 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,595 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,598 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2, remote_ref=defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069]
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,598 2968 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_modified: StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: modified, Remote state: synchronized, State: synchronized)
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,598 2968 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:True, State: locally_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,598 2968 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,599 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,599 2736 DEBUG nxdrive.engine.queue_manager creating local folder processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,601 2748 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(2748) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,602 2748 TRACE nxdrive.engine.dao.sqlite Acquired processor 2748 for row 6
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,604 2748 DEBUG nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: modified, Remote state: synchronized, State: locally_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,605 2748 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,605 2748 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#53afea78-50ee-43b0-a2ce-3b6499576069"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,618 2748 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#53afea78-50ee-43b0-a2ce-3b6499576069","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069","folder":true,"creationDate":1448015293030,"lastModificationDate":1448015293030,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,622 2748 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x0EF50260>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: modified, Remote state: synchronized, State: locally_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,622 2748 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,622 2748 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
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,627 2748 DEBUG nxdrive.engine.dao.sqlite Queuing 1 children of 'StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: modified, Remote state: synchronized, State: locally_modified)'
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,627 2748 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,628 2748 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_modified of <nxdrive.engine.processor.Processor object at 0x0EF50260>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: modified, Remote state: synchronized, State: locally_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,630 2748 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,630 2748 TRACE nxdrive.engine.dao.sqlite Released processor 2748
11:28:28 [INFO] [exec] 2015-11-20 11:28:14,631 2748 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(2748) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,582 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,582 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,582 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,582 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileDeletedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,582 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,582 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,582 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,582 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,585 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 2.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,585 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,585 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,592 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,594 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,601 2968 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
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,601 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,601 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,605 2968 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
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,607 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,607 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,608 2968 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1 as marked unsynchronized
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,608 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileDeletedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,608 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [deleted] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\.watchdog_setup'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,609 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,609 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,611 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 3 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538]
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,614 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,615 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,615 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 2 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2, remote_ref=defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069]
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,618 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,618 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,618 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 4 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538]
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,621 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,621 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,621 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 3 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 2, remote_ref=defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069]
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,622 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 2.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,622 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 2.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,628 2968 DEBUG nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original File 2.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,630 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,631 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,634 2968 DEBUG nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Original File 1.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,634 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,634 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 2\\Original File 3.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:15,637 2968 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
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,184 300 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,186 300 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 1525, 'lastSyncActiveRootDefinitions': u'default:ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,186 300 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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": 1525, "lastSyncActiveRootDefinitions": "default:ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,223 300 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"fileSystemChanges":[{"fileSystemItemName":"Original File 3.txt","fileSystemItem":{"digest":"180b2cbf65a05357269e12a1d1324635","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/b67ab505-e798-4fa2-91f1-aa5cabe76356/blobholder:0/Original%20File%203.txt","name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069/defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356","folder":false,"creationDate":1448015293254,"lastModificationDate":1448015293254,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356","eventId":"documentCreated","docUuid":"b67ab505-e798-4fa2-91f1-aa5cabe76356","repositoryId":"default","eventDate":1448015293254},{"fileSystemItemName":"Original File 1.txt","fileSystemItem":{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060/blobholder:0/Original%20File%201.txt","name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","folder":false,"creationDate":1448015293177,"lastModificationDate":1448015293177,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","eventId":"documentCreated","docUuid":"8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","repositoryId":"default","eventDate":1448015293177},{"fileSystemItemName":"Original File 2.txt","fileSystemItem":{"digest":"aa5728d0861fd3b174dc33202838ecb8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/28896da6-2d3f-40fb-9237-f4809dcd28a8/blobholder:0/Original%20File%202.txt","name":"Original File 2.txt","id":"defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8","folder":false,"creationDate":1448015293156,"lastModificationDate":1448015293156,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8","eventId":"documentCreated","docUuid":"28896da6-2d3f-40fb-9237-f4809dcd28a8","repositoryId":"default","eventDate":1448015293156},{"fileSystemItemName":"Original Folder 2","fileSystemItem":{"canCreateChild":true,"name":"Original Folder 2","id":"defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069","folder":true,"creationDate":1448015293030,"lastModificationDate":1448015293030,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069","eventId":"documentCreated","docUuid":"53afea78-50ee-43b0-a2ce-3b6499576069","repositoryId":"default","eventDate":1448015293030}],"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:ea414d64-7c4d-4675-825a-1b1eb195c538","upperBound":1553,"syncDate":1448015296000}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,223 300 DEBUG nxdrive.engine.watcher.remote_watcher 4 remote changes detected
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,223 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,224 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,226 2736 DEBUG nxdrive.tests.common_unit_test Remote changes slot for: 6559d2918f7111e59415080027915b3f
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,226 300 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'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True, u'downloadURL': u'nxfile/default/b67ab505-e798-4fa2-91f1-aa5cabe76356/blobholder:0/Original%20File%203.txt', u'parentId': u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069/defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356', u'folder': False, u'creationDate': 1448015293254L, u'lastModificationDate': 1448015293254L, u'id': u'defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356', u'digest': u'180b2cbf65a05357269e12a1d1324635'}, u'repositoryId': u'default', u'fileSystemItemName': u'Original File 3.txt', u'fileSystemItemId': u'defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356', u'docUuid': u'b67ab505-e798-4fa2-91f1-aa5cabe76356', u'eventDate': 1448015293254L}
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,230 300 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)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,230 300 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Original File 3.txt', uid=u'defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356', parent_uid=u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069/defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 11, 28, 13), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'180b2cbf65a05357269e12a1d1324635', digest_algorithm=u'md5', download_url=u'nxfile/default/b67ab505-e798-4fa2-91f1-aa5cabe76356/blobholder:0/Original%20File%203.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,233 300 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,233 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[10](Folderish:False, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,233 300 TRACE nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,234 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,236 2736 DEBUG nxdrive.engine.queue_manager creating remote file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,236 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,237 2956 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2956) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,243 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,244 2088 DEBUG nxdrive.engine.workers Thread GenericProcessor(2088) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,246 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,246 2088 DEBUG nxdrive.engine.workers Thread GenericProcessor(2088) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,250 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,247 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,250 2320 DEBUG nxdrive.engine.workers Thread GenericProcessor(2320) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,252 300 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'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True, u'downloadURL': u'nxfile/default/8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060/blobholder:0/Original%20File%201.txt', u'parentId': u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', u'folder': False, u'creationDate': 1448015293177L, u'lastModificationDate': 1448015293177L, u'id': u'defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', u'digest': u'f3b09f7a82f6ac8c6077a1ca1d3778d8'}, u'repositoryId': u'default', u'fileSystemItemName': u'Original File 1.txt', u'fileSystemItemId': u'defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', u'docUuid': u'8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', u'eventDate': 1448015293177L}
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,252 2956 TRACE nxdrive.engine.dao.sqlite Acquired processor 2956 for row 10
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,255 2320 DEBUG nxdrive.engine.workers Thread GenericProcessor(2320) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,259 2620 DEBUG nxdrive.engine.workers Thread GenericProcessor(2620) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,266 2620 DEBUG nxdrive.engine.workers Thread GenericProcessor(2620) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,267 300 DEBUG nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Original File 1.txt' (force_recursion:0)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,269 2956 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#b67ab505-e798-4fa2-91f1-aa5cabe76356, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,273 300 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Original File 1.txt', uid=u'defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', parent_uid=u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 11, 28, 13), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f3b09f7a82f6ac8c6077a1ca1d3778d8', digest_algorithm=u'md5', download_url=u'nxfile/default/8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060/blobholder:0/Original%20File%201.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,275 2956 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EE86F80>> on doc pair StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,278 2956 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,282 300 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,282 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:False, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,282 300 TRACE nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,286 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,289 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,289 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,290 2560 DEBUG nxdrive.engine.workers Thread GenericProcessor(2560) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,296 1260 DEBUG nxdrive.engine.workers Thread GenericProcessor(1260) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,296 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,302 1260 DEBUG nxdrive.engine.workers Thread GenericProcessor(1260) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,303 2956 DEBUG nxdrive.engine.processor No local impact of metadata update on document 'Original File 3.txt'.
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,312 2956 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
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,313 2560 TRACE nxdrive.engine.dao.sqlite Acquired processor 2560 for row 3
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,312 2428 DEBUG nxdrive.engine.workers Thread GenericProcessor(2428) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,322 2428 DEBUG nxdrive.engine.workers Thread GenericProcessor(2428) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,325 2560 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,328 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,331 2560 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EF50170>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,332 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,334 2560 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original File 1.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,335 300 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'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True, u'downloadURL': u'nxfile/default/28896da6-2d3f-40fb-9237-f4809dcd28a8/blobholder:0/Original%20File%202.txt', u'parentId': u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8', u'folder': False, u'creationDate': 1448015293156L, u'lastModificationDate': 1448015293156L, u'id': u'defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8', u'digest': u'aa5728d0861fd3b174dc33202838ecb8'}, u'repositoryId': u'default', u'fileSystemItemName': u'Original File 2.txt', u'fileSystemItemId': u'defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8', u'docUuid': u'28896da6-2d3f-40fb-9237-f4809dcd28a8', u'eventDate': 1448015293156L}
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,335 2956 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EE86F80>> on doc pair StateRow[10](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2/Original File 3.txt', Remote: defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,339 2956 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2/original file 3.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,345 2956 TRACE nxdrive.engine.dao.sqlite Released processor 2956
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,348 300 DEBUG nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Original File 2.txt' (force_recursion:0)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,348 2956 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2956) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,354 300 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Original File 2.txt', uid=u'defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8', parent_uid=u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 11, 28, 13), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'aa5728d0861fd3b174dc33202838ecb8', digest_algorithm=u'md5', download_url=u'nxfile/default/28896da6-2d3f-40fb-9237-f4809dcd28a8/blobholder:0/Original%20File%202.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,359 2560 DEBUG nxdrive.engine.processor No local impact of metadata update on document 'Original File 1.txt'.
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,361 2560 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
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,361 300 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,362 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:False, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,364 300 TRACE nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,365 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,367 2736 DEBUG nxdrive.engine.queue_manager creating remote file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,367 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,368 2560 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EF50170>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,368 2824 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2824) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,375 2560 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original file 1.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,378 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,380 952 DEBUG nxdrive.engine.workers Thread GenericProcessor(952) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,385 2824 TRACE nxdrive.engine.dao.sqlite Acquired processor 2824 for row 4
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,385 952 DEBUG nxdrive.engine.workers Thread GenericProcessor(952) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,387 2964 DEBUG nxdrive.engine.workers Thread GenericProcessor(2964) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,395 2560 TRACE nxdrive.engine.dao.sqlite Released processor 2560
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,395 2964 DEBUG nxdrive.engine.workers Thread GenericProcessor(2964) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,404 2560 DEBUG nxdrive.engine.workers Thread GenericProcessor(2560) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,414 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,411 2824 DEBUG nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,417 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,421 300 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'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True, u'canCreateChild': True, u'parentId': u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069', u'folder': True, u'creationDate': 1448015293030L, u'lastModificationDate': 1448015293030L, u'id': u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069'}, u'repositoryId': u'default', u'fileSystemItemName': u'Original Folder 2', u'fileSystemItemId': u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069', u'docUuid': u'53afea78-50ee-43b0-a2ce-3b6499576069', u'eventDate': 1448015293030L}
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,421 2824 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EF50620>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,424 2824 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original File 2.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,427 300 DEBUG nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Original Folder 2' (force_recursion:0)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,430 300 TRACE nxdrive.engine.dao.sqlite Increasing version to 4 for pair RemoteFileInfo(name=u'Original Folder 2', uid=u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069', parent_uid=u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069', folderish=True, last_modification_time=datetime.datetime(2015, 11, 20, 11, 28, 13), 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)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,436 300 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,436 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:True, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,436 300 TRACE nxdrive.engine.queue_manager Pushed to _remote_folder_queue, now of size: 1
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,437 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,440 2736 DEBUG nxdrive.engine.queue_manager creating remote folder processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,444 2824 DEBUG nxdrive.engine.processor No local impact of metadata update on document 'Original File 2.txt'.
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,447 856 DEBUG nxdrive.engine.workers Thread RemoteFolderProcessor(856) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,451 2824 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
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,453 300 DEBUG nxdrive.engine.watcher.remote_watcher Remote scanning: /Nuxeo Drive Test Workspace/Original Folder 2
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,454 300 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,456 300 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#53afea78-50ee-43b0-a2ce-3b6499576069"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,456 856 TRACE nxdrive.engine.dao.sqlite Acquired processor 856 for row 6
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,460 856 DEBUG nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,461 856 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EF50800>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,466 2824 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EF50620>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/Original File 2.txt', Remote: defaultFileSystemItemFactory#default#28896da6-2d3f-40fb-9237-f4809dcd28a8, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,466 856 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 2
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,469 2824 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original file 2.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,471 2824 TRACE nxdrive.engine.dao.sqlite Released processor 2824
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,476 2824 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2824) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,477 856 DEBUG nxdrive.engine.processor No local impact of metadata update on document 'Original Folder 2'.
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,480 856 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
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,482 856 DEBUG nxdrive.engine.dao.sqlite Queuing 1 children of 'StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: synchronized, Remote state: modified, State: remotely_modified)'
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,483 856 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,483 856 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EF50800>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Original Folder 2', Remote: defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,484 856 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 2
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,486 856 TRACE nxdrive.engine.dao.sqlite Released processor 856
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,486 856 DEBUG nxdrive.engine.workers Thread RemoteFolderProcessor(856) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,526 300 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/b67ab505-e798-4fa2-91f1-aa5cabe76356/blobholder:0/Original%20File%203.txt","name":"Original File 3.txt","id":"defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069/defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356","folder":false,"creationDate":1448015293254,"lastModificationDate":1448015293254,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"}]'
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,526 300 TRACE nxdrive.engine.watcher.remote_watcher Scanning remote child: RemoteFileInfo(name=u'Original File 3.txt', uid=u'defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356', parent_uid=u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069/defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 11, 28, 13), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'180b2cbf65a05357269e12a1d1324635', digest_algorithm=u'md5', download_url=u'nxfile/default/b67ab505-e798-4fa2-91f1-aa5cabe76356/blobholder:0/Original%20File%203.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,526 300 TRACE nxdrive.engine.dao.sqlite Increasing version to 2 for pair RemoteFileInfo(name=u'Original File 3.txt', uid=u'defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356', parent_uid=u'defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#53afea78-50ee-43b0-a2ce-3b6499576069/defaultFileSystemItemFactory#default#b67ab505-e798-4fa2-91f1-aa5cabe76356', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 11, 28, 13), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'180b2cbf65a05357269e12a1d1324635', digest_algorithm=u'md5', download_url=u'nxfile/default/b67ab505-e798-4fa2-91f1-aa5cabe76356/blobholder:0/Original%20File%203.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,532 300 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
11:28:28 [INFO] [exec] 2015-11-20 11:28:16,542 2736 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 0
11:28:28 [INFO] [exec] 2015-11-20 11:28:19,788 300 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
11:28:28 [INFO] [exec] 2015-11-20 11:28:19,789 300 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 1553, 'lastSyncActiveRootDefinitions': u'default:ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:19,789 300 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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": 1553, "lastSyncActiveRootDefinitions": "default:ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:19,803 300 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"fileSystemChanges":[],"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:ea414d64-7c4d-4675-825a-1b1eb195c538","upperBound":1557,"syncDate":1448015299000}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:19,803 2736 TRACE nxdrive.tests.common_unit_test No remote changes slot for: 6559d2918f7111e59415080027915b3f
11:28:28 [INFO] [exec] 2015-11-20 11:28:19,809 2736 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
11:28:28 [INFO] [exec] 2015-11-20 11:28:19,811 2736 DEBUG nxdrive.engine.engine Emitting syncCompleted for engine 6559d2918f7111e59415080027915b3f
11:28:28 [INFO] [exec] 2015-11-20 11:28:19,812 2736 DEBUG nxdrive.tests.common_unit_test Sync Completed slot for: 6559d2918f7111e59415080027915b3f
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,559 2468 DEBUG nxdrive.tests.common_unit_test Sync completed, ended wait for sync
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,559 2468 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 File 1.txt' AND ecm:currentLifeCycleState != 'deleted' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,559 2468 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTozODQxNTg='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:path = \'/default-domain/workspaces/nuxeo-drive-test-workspace/Original File 1.txt\' AND ecm:currentLifeCycleState != \'deleted\' AND ecm:isCheckedInVersion = 0 LIMIT 1"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,622 2468 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Query' with cookies []: '{"entity-type":"documents","isPaginable":true,"resultsCount":1,"pageSize":0,"maxPageSize":1000,"currentPageSize":1,"currentPageIndex":0,"numberOfPages":1,"isPreviousPageAvailable":false,"isNextPageAvailable":false,"isLastPageAvailable":false,"isSortable":true,"hasError":false,"errorMessage":null,"totalSize":1,"pageIndex":0,"pageCount":1,"entries":[{"entity-type":"document","repository":"default","uid":"8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Original File 1.txt","type":"Note","state":"project","parentRef":"ea414d64-7c4d-4675-825a-1b1eb195c538","isCheckedOut":true,"changeToken":"1448015293177","title":"Original File 1.txt","lastModified":"2015-11-20T10:28:13.17Z","properties":{"note:note":"Some Content 1","note:mime_type":"text/plain","uid:uid":null,"uid:major_version":0,"uid:minor_version":0,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/note.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-11-20T10:28:13.17Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-20T10:28:13.17Z","dc:title":"Original File 1.txt","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null,"relatedtext:relatedtextresources":[]},"facets":["Versionable","Publishable","Commentable","HasRelatedText"]}]}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,622 2468 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace/Original File 1.txt'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,625 2468 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTozODQxNTg='}, cookies [] and JSON payload '{"params": {"value": "/default-domain/workspaces/nuxeo-drive-test-workspace/Original File 1.txt"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,637 2468 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/Original File 1.txt","type":"Note","state":"project","parentRef":"ea414d64-7c4d-4675-825a-1b1eb195c538","isCheckedOut":true,"changeToken":"1448015293177","title":"Original File 1.txt","lastModified":"2015-11-20T10:28:13.17Z","properties":{"note:note":"Some Content 1","note:mime_type":"text/plain","uid:uid":null,"uid:major_version":0,"uid:minor_version":0,"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/note.gif","files:files":[],"dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-11-20T10:28:13.17Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-20T10:28:13.17Z","dc:title":"Original File 1.txt","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null,"relatedtext:relatedtextresources":[]},"facets":["Versionable","Publishable","Commentable","HasRelatedText"]}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,638 2468 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,638 2468 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTozODQxNTg='}, cookies [] and JSON payload '{"params": {"value": "/default-domain/workspaces/nuxeo-drive-test-workspace"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,648 2468 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"ea414d64-7c4d-4675-825a-1b1eb195c538","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"1491093d-59ef-4f2e-82ae-9247719a1dc2","isCheckedOut":true,"changeToken":"1448015290504","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-20T10:28:10.50Z","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-20T10:28:10.50Z","dc:lastContributor":"nuxeoDriveTestUser_user_2","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-20T10:28:09.85Z","dc:title":"Nuxeo Drive Test Workspace","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["Administrator","nuxeoDriveTestUser_user_1","nuxeoDriveTestUser_user_2"],"dc:source":null,"dc:publisher":null,"drv:subscriptions":[{"lastChangeDate":"2015-11-20T10:28:10.42Z","enabled":true,"username":"nuxeoDriveTestUser_user_1"},{"lastChangeDate":"2015-11-20T10:28:10.50Z","enabled":true,"username":"nuxeoDriveTestUser_user_2"}],"publish:sections":[]},"facets":["DriveSynchronized","Folderish","SuperSpace"]}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,654 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileDeletedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,657 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Renamed File 1 \xe9.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,660 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,660 2468 DEBUG nxdrive.tests.common_unit_test Wait for sync
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,663 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileDeletedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,664 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [deleted] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original File 1.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,665 2968 DEBUG nxdrive.engine.watcher.local_watcher Add pair to delete events: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: synchronized, State: synchronized)
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,665 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Renamed File 1 \xe9.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,665 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Renamed File 1 \xe9.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,667 2968 DEBUG nxdrive.engine.watcher.local_watcher Found creation in delete event, handle move instead
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,667 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 2 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1\Renamed File 1 .txt, remote_ref=defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060]
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,667 2968 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_moved: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original File 1.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: moved, Remote state: synchronized, State: synchronized)
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,668 2968 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:False, State: locally_moved)
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,668 2968 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,670 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,670 2736 DEBUG nxdrive.engine.queue_manager creating local file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,671 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,671 2328 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(2328) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,671 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,673 3004 DEBUG nxdrive.engine.workers Thread GenericProcessor(3004) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,674 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,680 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,681 3004 DEBUG nxdrive.engine.workers Thread GenericProcessor(3004) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,684 2328 TRACE nxdrive.engine.dao.sqlite Acquired processor 2328 for row 3
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,687 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,687 1108 DEBUG nxdrive.engine.workers Thread GenericProcessor(1108) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,697 1108 DEBUG nxdrive.engine.workers Thread GenericProcessor(1108) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,700 2292 DEBUG nxdrive.engine.workers Thread GenericProcessor(2292) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,709 2328 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 \xe9.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: moved, Remote state: synchronized, State: locally_moved)
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,710 2292 DEBUG nxdrive.engine.workers Thread GenericProcessor(2292) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,710 2968 DEBUG nxdrive.engine.watcher.local_watcher Ignoring /Nuxeo Drive Test Workspace/Original Folder 1 as marked unsynchronized
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,717 2328 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,720 2328 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,734 2328 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060/blobholder:0/Original%20File%201.txt","name":"Original File 1.txt","id":"defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","folder":false,"creationDate":1448015293177,"lastModificationDate":1448015293177,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,739 2328 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_moved of <nxdrive.engine.processor.Processor object at 0x0EF50440>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 \xe9.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: moved, Remote state: synchronized, State: locally_moved)
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,740 2328 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 é.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,740 2328 DEBUG nxdrive.engine.processor Renaming remote file according to local : StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 \xe9.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: moved, Remote state: synchronized, State: locally_moved)
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,740 2328 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', 'name': u'Renamed File 1 \xe9.txt'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,740 2328 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Rename with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060", "name": "Renamed File 1 \\u00e9.txt"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,762 2328 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.Rename' with cookies []: '{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060/blobholder:0/Renamed%20File%201%20%C3%A9.txt","name":"Renamed File 1 \xc3\xa9.txt","id":"defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","folder":false,"creationDate":1448015293177,"lastModificationDate":1448015300751,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,769 2328 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 é.txt, remote_name=Original File 1.txt, version=2] with version=2
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,772 2328 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_moved of <nxdrive.engine.processor.Processor object at 0x0EF50440>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 \xe9.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: moved, Remote state: synchronized, State: locally_moved)
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,772 2328 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1/renamed file 1 é.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,773 2328 TRACE nxdrive.engine.dao.sqlite Released processor 2328
11:28:28 [INFO] [exec] 2015-11-20 11:28:20,773 2328 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(2328) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,068 300 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,069 300 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 1557, 'lastSyncActiveRootDefinitions': u'default:ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,069 300 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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": 1557, "lastSyncActiveRootDefinitions": "default:ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,092 300 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"fileSystemChanges":[{"fileSystemItemName":"Renamed File 1 \xc3\xa9.txt","fileSystemItem":{"digest":"f3b09f7a82f6ac8c6077a1ca1d3778d8","digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060/blobholder:0/Renamed%20File%201%20%C3%A9.txt","name":"Renamed File 1 \xc3\xa9.txt","id":"defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","folder":false,"creationDate":1448015293177,"lastModificationDate":1448015300751,"lastContributor":"nuxeoDriveTestUser_user_1","creator":"nuxeoDriveTestUser_user_1","parentId":"defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538","canDelete":true,"canRename":true,"userName":"nuxeoDriveTestUser_user_1"},"fileSystemItemId":"defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","eventId":"documentModified","docUuid":"8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060","repositoryId":"default","eventDate":1448015300752}],"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:ea414d64-7c4d-4675-825a-1b1eb195c538","upperBound":1567,"syncDate":1448015303000}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,092 300 DEBUG nxdrive.engine.watcher.remote_watcher 1 remote changes detected
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,092 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,094 300 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,094 2736 DEBUG nxdrive.tests.common_unit_test Remote changes slot for: 6559d2918f7111e59415080027915b3f
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,095 300 TRACE nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentModified', u'fileSystemItem': {u'canUpdate': True, u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'Renamed File 1 \xe9.txt', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'digestAlgorithm': u'MD5', u'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True, u'downloadURL': u'nxfile/default/8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060/blobholder:0/Renamed%20File%201%20%C3%A9.txt', u'parentId': u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', u'folder': False, u'creationDate': 1448015293177L, u'lastModificationDate': 1448015300751L, u'id': u'defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', u'digest': u'f3b09f7a82f6ac8c6077a1ca1d3778d8'}, u'repositoryId': u'default', u'fileSystemItemName': u'Renamed File 1 \xe9.txt', u'fileSystemItemId': u'defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', u'docUuid': u'8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', u'eventDate': 1448015300752L}
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,098 300 DEBUG nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 é.txt' (force_recursion:0)
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,098 300 TRACE nxdrive.engine.dao.sqlite Increasing version to 3 for pair RemoteFileInfo(name=u'Renamed File 1 \xe9.txt', uid=u'defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', parent_uid=u'defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538/defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060', folderish=False, last_modification_time=datetime.datetime(2015, 11, 20, 11, 28, 20), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f3b09f7a82f6ac8c6077a1ca1d3778d8', digest_algorithm=u'md5', download_url=u'nxfile/default/8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060/blobholder:0/Renamed%20File%201%20%C3%A9.txt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,101 300 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,101 300 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:False, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,101 300 TRACE nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,101 2736 TRACE nxdrive.engine.queue_manager Launching processors
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,102 2736 DEBUG nxdrive.engine.queue_manager creating remote file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,102 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,104 2940 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2940) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,104 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,105 1336 DEBUG nxdrive.engine.workers Thread GenericProcessor(1336) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,112 1336 DEBUG nxdrive.engine.workers Thread GenericProcessor(1336) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,115 2940 TRACE nxdrive.engine.dao.sqlite Acquired processor 2940 for row 3
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,115 2736 DEBUG nxdrive.engine.queue_manager creating additional file processor
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,117 1508 DEBUG nxdrive.engine.workers Thread GenericProcessor(1508) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,125 1508 DEBUG nxdrive.engine.workers Thread GenericProcessor(1508) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,131 2856 DEBUG nxdrive.engine.workers Thread GenericProcessor(2856) start
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,135 2940 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 \xe9.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,138 2856 DEBUG nxdrive.engine.workers Thread GenericProcessor(2856) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,148 2940 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EF50210>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 \xe9.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,150 2940 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 é.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,161 2736 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is active, overall size = 0, empty polls count = 0
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,165 2940 DEBUG nxdrive.engine.processor DOC_PAIR(StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 \xe9.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: modified, State: remotely_modified)): old_path[1]['defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060']: /Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 é.txt, new_path[0][None]: /Nuxeo Drive Test Workspace/Renamed File 1 é.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,165 2940 DEBUG nxdrive.engine.processor Moving local file '\\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Original Folder 1\Renamed File 1 é.txt' to '\\?\C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace\Renamed File 1 é.txt'.
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,180 2940 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Renamed File 1 é.txt, remote_name=Renamed File 1 é.txt, version=3] with version=3
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,183 2940 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x0EF50210>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Renamed File 1 \xe9.txt', Remote: defaultFileSystemItemFactory#default#8f0eb1b1-3aaa-484a-bcb5-4e49c7b96060, Local state: synchronized, Remote state: modified, State: remotely_modified)
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,184 2940 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/original folder 1/renamed file 1 é.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,184 2940 TRACE nxdrive.engine.dao.sqlite Released processor 2940
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,184 2940 DEBUG nxdrive.engine.workers Thread RemoteFileProcessor(2940) end
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,190 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,191 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileDeletedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Renamed File 1 \xe9.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,191 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Renamed File 1 \xe9.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,193 3060 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,194 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,194 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,197 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 5 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538]
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,200 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileDeletedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Renamed File 1 \xe9.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,200 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [deleted] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Original Folder 1\\Renamed File 1 \xe9.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,200 2968 DEBUG nxdrive.engine.watcher.local_watcher Unknown pair deleted: /Nuxeo Drive Test Workspace/Original Folder 1/Renamed File 1 é.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,200 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Renamed File 1 \xe9.txt'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,200 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace\\Renamed File 1 \xe9.txt'
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,206 2968 DEBUG nxdrive.engine.watcher.local_watcher Dropping watchdog event [created] as digest has not changed for /Nuxeo Drive Test Workspace/Renamed File 1 é.txt
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,206 2968 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'>
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,206 2968 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'C:\\Jenkins\\workspace\\FT-nuxeo-drive-master-windows\\tmp\\tmpileubc-nxdrive-tests-user-1\\Nuxeo Drive\\Nuxeo Drive Test Workspace'
11:28:28 [INFO] [exec] 2015-11-20 11:28:23,207 2968 TRACE nxdrive.engine.dao.sqlite Increasing version to 6 for pair FileInfo[C:\Jenkins\workspace\FT-nuxeo-drive-master-windows\tmp\tmpileubc-nxdrive-tests-user-1\Nuxeo Drive\Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#ea414d64-7c4d-4675-825a-1b1eb195c538]
11:28:28 [INFO] [exec] 2015-11-20 11:28:26,397 300 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
11:28:28 [INFO] [exec] 2015-11-20 11:28:26,398 300 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 1567, 'lastSyncActiveRootDefinitions': u'default:ea414d64-7c4d-4675-825a-1b1eb195c538'}}
11:28:28 [INFO] [exec] 2015-11-20 11:28:26,398 300 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '8820f858-5a2b-475e-ac71-ad246170ce07', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6540cc518f7111e5ba03080027915b3f', '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": 1567, "lastSyncActiveRootDefinitions": "default:ea414d64-7c4d-4675-825a-1b1eb195c538"}}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:26,417 300 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"fileSystemChanges":[],"hasTooManyChanges":false,"activeSynchronizationRootDefinitions":"default:ea414d64-7c4d-4675-825a-1b1eb195c538","upperBound":1569,"syncDate":1448015306000}'
11:28:28 [INFO] [exec] 2015-11-20 11:28:26,418 2736 TRACE nxdrive.tests.common_unit_test No remote changes slot for: 6559d2918f7111e59415080027915b3f
11:28:28 [INFO] [exec] 2015-11-20 11:28:26,426 2736 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
11:28:28 [INFO] [exec] 2015-11-20 11:28:26,428 2736 DEBUG nxdrive.engine.engine Emitting syncCompleted for engine 6559d2918f7111e59415080027915b3f
11:28:28 [INFO] [exec] 2015-11-20 11:28:26,430 2736 DEBUG nxdrive.tests.common_unit_test Sync Completed slot for: 6559d2918f7111e59415080027915b3f
11:28:28 [INFO] [exec] 2015-11-20 11:28:26,670 2468 DEBUG nxdrive.tests.common_unit_test Sync completed, ended wait for sync
11:28:28 [INFO] [exec] --------------------- >> end captured logging << ---------------------
NXDRIVE-483 Fix concurrent local scan
