Minor http://qa.nuxeo.org/jenkins/view/Drive/job/FT-nuxeo-drive-master-linux/1494/console
19:21:14 [INFO] [exec] ======================================================================
19:21:14 [INFO] [exec] FAIL: test_synchronize_local_office_temp (nxdrive.tests.test_local_filter.TestLocalFilter)
19:21:14 [INFO] [exec] ----------------------------------------------------------------------
19:21:14 [INFO] [exec] Traceback (most recent call last):
19:21:14 [INFO] [exec] File "/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/tests/test_local_filter.py", line 91, in test_synchronize_local_office_temp
19:21:14 [INFO] [exec] self.assertTrue(self.local_client_1.exists("/" + hexafile + ".txt"))
19:21:14 [INFO] [exec] AssertionError: False is not true
19:21:14 [INFO] [exec] -------------------- >> begin captured logging << --------------------
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,244 140201963087680 DEBUG nxdrive.engine.dao.sqlite Create DAO on /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,244 140201963087680 DEBUG nxdrive.engine.dao.sqlite Create main connexion on /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,451 140201963087680 DEBUG nxdrive.osi Not using any OS integration
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,485 140201963087680 DEBUG nxdrive.updater Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,518 140201963087680 DEBUG nxdrive.engine.dao.sqlite Create DAO on /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpJ2uRYi-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,519 140201963087680 DEBUG nxdrive.engine.dao.sqlite Create main connexion on /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpJ2uRYi-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,677 140201963087680 DEBUG nxdrive.osi Not using any OS integration
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,711 140201963087680 DEBUG nxdrive.updater Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,712 140201963087680 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,713 140201963087680 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 []
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,739 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/'}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,739 140201963087680 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": "/"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,743 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"371cea4f-f97b-4aea-a170-5293f5cd1ea1","path":"/","type":"Root","state":null,"parentRef":"/","isCheckedOut":true,"changeToken":null,"title":"371cea4f-f97b-4aea-a170-5293f5cd1ea1","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"]}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,744 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,744 140201963087680 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"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,802 140201963087680 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'
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,836 140201963087680 DEBUG nxdrive.engine.dao.sqlite Create DAO on /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_6f37df8e946a11e5b009d067e5f2a1a2.db
19:21:14 [INFO] [exec] 2015-11-26 19:20:55,837 140201963087680 DEBUG nxdrive.engine.dao.sqlite Create main connexion on /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_6f37df8e946a11e5b009d067e5f2a1a2.db (dir exists: 1 / file exists: 0)
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,004 140201963087680 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,045 140201963087680 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite finished
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,047 140201963087680 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,047 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjMjFkMzA='} and cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,065 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Linux+Desktop&revoke=false&deviceId=6f0236c2946a11e5b009d067e5f2a1a2&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjMjFkMzA='} and cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,081 140201963087680 TRACE nxdrive.client.base_automation_client Got token 'de099c19-ed99-43ee-9fb2-c8957ca18dc1' with cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,195 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,196 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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": {}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,200 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"8.1-SNAPSHOT","updateSiteURL":"http://community.nuxeo.com/static/drive/","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/"}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,200 140201963087680 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/'}
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,282 140201963087680 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,282 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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 []
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,303 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,303 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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": {}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,308 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"creationDate":306,"creator":"system","folder":true,"parentId":null,"canRename":false,"canDelete":false,"lastContributor":"system","lastModificationDate":306,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_1"}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,309 140201963087680 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,371 140201963087680 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,372 140201963087680 TRACE nxdrive.client.local_client Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_1|6f0236c2946a11e5b009d067e5f2a1a2|6f37df8e946a11e5b009d067e5f2a1a2' on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,372 140201963087680 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0 and state=synchronized
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,405 140201963087680 DEBUG nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[1](Local: u'/', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,439 140201963087680 DEBUG nxdrive.engine.dao.sqlite Create DAO on /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpJ2uRYi-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_6f9459ee946a11e5b009d067e5f2a1a2.db
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,439 140201963087680 DEBUG nxdrive.engine.dao.sqlite Create main connexion on /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpJ2uRYi-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_6f9459ee946a11e5b009d067e5f2a1a2.db (dir exists: 1 / file exists: 0)
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,607 140201963087680 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,640 140201963087680 TRACE nxdrive.engine.dao.sqlite Vacuum sqlite finished
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,641 140201963087680 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,642 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6f24c070946a11e5b009d067e5f2a1a2', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpkYjkxODg='} and cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,664 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Linux+Desktop&revoke=false&deviceId=6f24c070946a11e5b009d067e5f2a1a2&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6f24c070946a11e5b009d067e5f2a1a2', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpkYjkxODg='} and cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,685 140201963087680 TRACE nxdrive.client.base_automation_client Got token '806d1356-ce5a-4690-8a69-79502f231f09' with cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,858 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,858 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '806d1356-ce5a-4690-8a69-79502f231f09', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f24c070946a11e5b009d067e5f2a1a2', '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": {}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,864 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"serverVersion":"8.1-SNAPSHOT","updateSiteURL":"http://community.nuxeo.com/static/drive/","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/"}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,864 140201963087680 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/'}
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,968 140201963087680 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,968 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '806d1356-ce5a-4690-8a69-79502f231f09', 'X-Device-Id': '6f24c070946a11e5b009d067e5f2a1a2', '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 []
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,986 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,986 140201963087680 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '806d1356-ce5a-4690-8a69-79502f231f09', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f24c070946a11e5b009d067e5f2a1a2', '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": {}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,991 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"creationDate":989,"creator":"system","folder":true,"parentId":null,"canRename":false,"canDelete":false,"lastContributor":"system","lastModificationDate":989,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_2"}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:56,991 140201963087680 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,050 140201963087680 TRACE nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,051 140201963087680 TRACE nxdrive.client.local_client Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_2|6f24c070946a11e5b009d067e5f2a1a2|6f9459ee946a11e5b009d067e5f2a1a2' on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpJ2uRYi-nxdrive-tests-user-2/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,051 140201963087680 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0 and state=synchronized
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,084 140201963087680 DEBUG nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[1](Local: u'/', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,088 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,088 140201963087680 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"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,098 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"94d55519-a17d-4edc-ae58-18d215879c1b","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"42d51920-5947-4c53-ac87-ca4804ddb3fa","isCheckedOut":true,"changeToken":"1448562055768","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-26T18:20:55.76Z","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-26T18:20:55.76Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-26T18:20:55.76Z","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"]}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,100 140201963087680 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,100 140201963087680 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjMjFkMzA='} and cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,118 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'94d55519-a17d-4edc-ae58-18d215879c1b'}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,118 140201963087680 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjMjFkMzA='}, cookies [] and JSON payload '{"params": {"value": "94d55519-a17d-4edc-ae58-18d215879c1b"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,122 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"94d55519-a17d-4edc-ae58-18d215879c1b","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"42d51920-5947-4c53-ac87-ca4804ddb3fa","isCheckedOut":true,"changeToken":"1448562055768","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-26T18:20:55.76Z","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-26T18:20:55.76Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-26T18:20:55.76Z","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"]}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,124 140201963087680 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,124 140201963087680 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpkYjkxODg='} and cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,141 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'94d55519-a17d-4edc-ae58-18d215879c1b'}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,141 140201963087680 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpkYjkxODg='}, cookies [] and JSON payload '{"params": {"value": "94d55519-a17d-4edc-ae58-18d215879c1b"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,145 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"94d55519-a17d-4edc-ae58-18d215879c1b","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"42d51920-5947-4c53-ac87-ca4804ddb3fa","isCheckedOut":true,"changeToken":"1448562055768","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-26T18:20:55.76Z","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-26T18:20:55.76Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-26T18:20:55.76Z","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"]}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,146 140201963087680 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,146 140201963087680 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjMjFkMzA='} and cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,164 140201963087680 DEBUG nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,165 140201963087680 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpkYjkxODg='} and cookies []
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,180 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'input': u'doc:94d55519-a17d-4edc-ae58-18d215879c1b', 'params': {'enable': True}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,180 140201963087680 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjMjFkMzA='}, cookies [] and JSON payload '{"input": "doc:94d55519-a17d-4edc-ae58-18d215879c1b", "params": {"enable": true}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,219 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,219 140201963087680 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'input': u'doc:94d55519-a17d-4edc-ae58-18d215879c1b', 'params': {'enable': True}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,219 140201963087680 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjpkYjkxODg='}, cookies [] and JSON payload '{"input": "doc:94d55519-a17d-4edc-ae58-18d215879c1b", "params": {"enable": true}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,278 140201963087680 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
19:21:14 [INFO] [exec] 2015-11-26 19:20:57,278 140201752352512 DEBUG nxdrive.tests.common_unit_test UnitTest thread started
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,280 140201752352512 TRACE nxdrive.client.local_client Setting xattr drive-fs-test with value 'NXDRIVE_VERIFICATION' on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,281 140201752352512 TRACE nxdrive.client.local_client Removing xattr drive-fs-test from /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,282 140201752352512 DEBUG nxdrive.engine.engine Engine start
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,282 140201752352512 DEBUG nxdrive.tests.common_unit_test Wait for sync
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,283 140201760745216 DEBUG nxdrive.engine.workers Thread LocalWatcher(140201760745216) start
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,283 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Watching FS modification on : /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,285 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,285 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup, wd=1, mask=IN_CREATE, cookie=0, name=.watchdog_setup>
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,286 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup, wd=1, mask=IN_ATTRIB, cookie=0, name=.watchdog_setup>
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,799 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,799 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,799 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:58,800 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,287 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup, wd=1, mask=IN_DELETE, cookie=0, name=.watchdog_setup>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,288 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,289 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Watchdog setup finished
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,289 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Full scan started
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,290 140201760745216 DEBUG nxdrive.engine.queue_manager Suspending queue
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,290 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Starting recursive local scan of u'/'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,290 140201760745216 TRACE nxdrive.engine.watcher.local_watcher Starting to get DB local children for u'/'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,291 140201760745216 TRACE nxdrive.engine.watcher.local_watcher Fetched DB local children for u'/'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,291 140201760745216 TRACE nxdrive.engine.watcher.local_watcher Starting to get FS children info for u'/'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,292 140201760745216 TRACE nxdrive.engine.watcher.local_watcher Fetched FS children info for u'/'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,292 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Ended recursive local scan of u'/'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,292 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Full scan finished in 3ms
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,292 140201760745216 DEBUG nxdrive.engine.queue_manager Resuming queue
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,293 140200550332160 DEBUG nxdrive.engine.workers Thread RemoteWatcher(140200550332160) start
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,294 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=True
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,294 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Remote full scan
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,295 140200550332160 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,295 140200550332160 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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#"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,303 140200550332160 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"creationDate":300,"creator":"system","folder":true,"parentId":null,"canRename":false,"canDelete":false,"lastContributor":"system","lastModificationDate":300,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_1"}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,303 140200550332160 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)
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,303 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,304 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,304 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,305 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,343 140200550332160 TRACE nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,343 140200550332160 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,343 140200550332160 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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": {}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,359 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,359 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,360 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,360 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,377 140200550332160 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":2241,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:94d55519-a17d-4edc-ae58-18d215879c1b","syncDate":1448562059000}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,477 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Remote scanning: /
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,477 140200550332160 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,478 140200550332160 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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#"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,492 140200550332160 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"creationDate":1448562055768,"creator":"Administrator","folder":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_2","lastModificationDate":1448562057244,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b","userName":"nuxeoDriveTestUser_user_1"}]'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,492 140200550332160 TRACE nxdrive.engine.watcher.remote_watcher Scanning remote child: RemoteFileInfo(name=u'Nuxeo Drive Test Workspace', uid=u'defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b', parent_uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b', folderish=True, last_modification_time=datetime.datetime(2015, 11, 26, 19, 20, 57), 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)
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,527 140200550332160 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_created: None
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,527 140200550332160 TRACE nxdrive.engine.queue_manager Pushing QueueItem[2](Folderish:True, State: remotely_created)
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,527 140200550332160 TRACE nxdrive.engine.queue_manager Pushed to _remote_folder_queue, now of size: 1
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,528 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Remote scanning: /Nuxeo Drive Test Workspace
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,529 140200550332160 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b'}}
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,529 140200550332160 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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#94d55519-a17d-4edc-ae58-18d215879c1b"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,547 140200550332160 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,677 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Remote scan finished in 383ms
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,678 140201963087680 DEBUG nxdrive.tests.common_unit_test Remote scan completed for engine 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,678 140201963087680 TRACE nxdrive.engine.queue_manager Init processors
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,678 140201963087680 TRACE nxdrive.engine.queue_manager Launching processors
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,678 140201963087680 DEBUG nxdrive.engine.queue_manager creating remote folder processor
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,679 140200533546752 DEBUG nxdrive.engine.workers Thread RemoteFolderProcessor(140200533546752) start
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,711 140200533546752 TRACE nxdrive.engine.dao.sqlite Acquired processor 140200533546752 for row 2
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,712 140200533546752 DEBUG nxdrive.engine.processor Executing processor on StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: unknown, Remote state: created, State: remotely_created)(0)
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,712 140200533546752 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f83035d0cc8>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: unknown, Remote state: created, State: remotely_created)
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,712 140200533546752 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,713 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,713 140200533546752 TRACE nxdrive.engine.processor readonly unlock: unlock on / with 1
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,714 140200653342464 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Nuxeo Drive>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,715 140200533546752 DEBUG nxdrive.engine.processor Creating local folder 'Nuxeo Drive Test Workspace' in '/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,716 140200533546752 TRACE nxdrive.engine.processor readonly lock: update lock count on / to 0
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,717 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=1, mask=IN_CREATE|IN_ISDIR, cookie=0, name=Nuxeo Drive Test Workspace>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,718 140200533546752 TRACE nxdrive.engine.processor readonly lock: relocked path: / with 1
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,718 140200653342464 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Nuxeo Drive>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,718 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,719 140200533546752 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b' on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,720 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Nuxeo Drive Test Workspace>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,721 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,721 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Nuxeo Drive Test Workspace>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,722 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,761 140200533546752 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace, remote_name=Nuxeo Drive Test Workspace, version=0] with version=0 and state=synchronized
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,795 140200533546752 DEBUG nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: unknown, Remote state: created, State: remotely_created)'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,795 140200533546752 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f83035d0cc8>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: unknown, Remote state: created, State: remotely_created)
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,795 140200533546752 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,795 140200533546752 TRACE nxdrive.engine.dao.sqlite No processor to release with id 140200533546752
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,795 140200533546752 DEBUG nxdrive.engine.workers Thread RemoteFolderProcessor(140200533546752) end
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,800 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileDeletedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,800 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,806 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileDeletedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,806 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [deleted] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,807 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:20:59,807 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,215 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,218 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,219 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,220 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,222 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,222 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,222 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,223 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,223 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,223 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event <DirCreatedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,224 140201760745216 TRACE nxdrive.engine.watcher.local_watcher This should only happen in case of a quick move and copy-paste
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,224 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,224 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,224 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,225 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,225 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive'
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,225 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,225 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,226 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,226 140201760745216 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b]
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,255 140200541939456 TRACE nxdrive.engine.watcher.local_watcher DriveFSROOT: Nuxeo Drive : need: Nuxeo Drive
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,261 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,262 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,262 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:00,263 140201760745216 TRACE nxdrive.engine.dao.sqlite Increasing version to 2 for pair FileInfo[/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b]
19:21:14 [INFO] [exec] 2015-11-26 19:21:02,728 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
19:21:14 [INFO] [exec] 2015-11-26 19:21:02,729 140200550332160 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 2241, 'lastSyncActiveRootDefinitions': u'default:94d55519-a17d-4edc-ae58-18d215879c1b'}}
19:21:14 [INFO] [exec] 2015-11-26 19:21:02,729 140200550332160 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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": 2241, "lastSyncActiveRootDefinitions": "default:94d55519-a17d-4edc-ae58-18d215879c1b"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:02,741 140200550332160 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":2249,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:94d55519-a17d-4edc-ae58-18d215879c1b","syncDate":1448562062000}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:02,741 140201963087680 TRACE nxdrive.tests.common_unit_test No remote changes slot for: 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:02,821 140201963087680 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
19:21:14 [INFO] [exec] 2015-11-26 19:21:02,845 140201963087680 DEBUG nxdrive.engine.engine Emitting syncCompleted for engine 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:02,846 140201963087680 DEBUG nxdrive.tests.common_unit_test Sync Completed slot for: 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,288 140201752352512 DEBUG nxdrive.tests.common_unit_test Sync completed, ended wait for sync
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,290 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD, wd=2, mask=IN_CREATE|IN_ISDIR, cookie=0, name=1234ABCD>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,291 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF, wd=2, mask=IN_CREATE, cookie=0, name=2345BCDF>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,292 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF, wd=2, mask=IN_MODIFY, cookie=0, name=2345BCDF>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,293 140201752352512 DEBUG nxdrive.tests.common_unit_test Wait for sync
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,840 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,840 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,840 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,841 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,841 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,842 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,842 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,843 140201760745216 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,843 140201760745216 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:True, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,844 140201760745216 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,844 140201963087680 TRACE nxdrive.engine.queue_manager Launching processors
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,844 140201963087680 DEBUG nxdrive.engine.queue_manager creating local folder processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,845 140200533546752 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(140200533546752) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,880 140201760745216 DEBUG nxdrive.engine.queue_manager Suspending queue
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,880 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Starting recursive local scan of u'/Nuxeo Drive Test Workspace/1234ABCD'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,880 140201760745216 TRACE nxdrive.engine.watcher.local_watcher Starting to get DB local children for u'/Nuxeo Drive Test Workspace/1234ABCD'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,913 140200533546752 TRACE nxdrive.engine.dao.sqlite Acquired processor 140200533546752 for row 3
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,913 140200533546752 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: None, Local state: created, Remote state: unknown, State: locally_created)(0)
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,914 140201760745216 TRACE nxdrive.engine.watcher.local_watcher Fetched DB local children for u'/Nuxeo Drive Test Workspace/1234ABCD'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,914 140201760745216 TRACE nxdrive.engine.watcher.local_watcher Starting to get FS children info for u'/Nuxeo Drive Test Workspace/1234ABCD'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,915 140200533546752 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f83024f3180>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,915 140200533546752 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/1234ABCD
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,915 140201760745216 TRACE nxdrive.engine.watcher.local_watcher Fetched FS children info for u'/Nuxeo Drive Test Workspace/1234ABCD'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,916 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Ended recursive local scan of u'/Nuxeo Drive Test Workspace/1234ABCD'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,916 140201760745216 DEBUG nxdrive.engine.queue_manager Resuming queue
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,917 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,917 140200533546752 TRACE nxdrive.engine.processor Entered _synchronize_locally_created, parent_pair = StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,917 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,917 140200533546752 DEBUG nxdrive.engine.processor Creating remote folder '1234ABCD' in folder 'Nuxeo Drive Test Workspace'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,918 140200533546752 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'name': u'1234ABCD', 'parentId': u'defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b'}}
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,918 140200533546752 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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": "1234ABCD", "parentId": "defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,919 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,920 140201760745216 TRACE nxdrive.engine.dao.sqlite Increasing version to 3 for pair FileInfo[/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b]
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,954 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,955 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,956 140201760745216 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,956 140201760745216 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:False, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,956 140201760745216 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,956 140201963087680 TRACE nxdrive.engine.queue_manager Launching processors
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,957 140201963087680 DEBUG nxdrive.engine.queue_manager creating local file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,957 140201963087680 DEBUG nxdrive.engine.queue_manager creating additional file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,958 140200525154048 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(140200525154048) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,958 140201963087680 DEBUG nxdrive.engine.queue_manager creating additional file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,959 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,959 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,959 140201963087680 DEBUG nxdrive.engine.queue_manager creating additional file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,959 140200508368640 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200508368640) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,959 140200508368640 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200508368640) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,960 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,960 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,978 140200533546752 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"creationDate":1448562063945,"creator":"nuxeoDriveTestUser_user_1","folder":true,"parentId":"defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448562063945,"name":"1234ABCD","id":"defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b/defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1","userName":"nuxeoDriveTestUser_user_1"}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,996 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,996 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,997 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:03,997 140201760745216 TRACE nxdrive.engine.dao.sqlite Increasing version to 4 for pair FileInfo[/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b]
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,038 140200525154048 TRACE nxdrive.engine.dao.sqlite Acquired processor 140200525154048 for row 4
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,080 140200533546752 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,080 140200533546752 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:True, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,080 140200533546752 TRACE nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,080 140200533546752 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,081 140200533546752 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1' on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD'
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,081 140201963087680 TRACE nxdrive.engine.queue_manager Launching processors
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,082 140200533546752 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/1234ABCD, remote_name=None, version=0] with version=0 and state=synchronized
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,082 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=1234ABCD>
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,083 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD, wd=3, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,083 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=1234ABCD>
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,084 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD, wd=3, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,122 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,122 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,123 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'> on known pair: StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,123 140201760745216 TRACE nxdrive.engine.watcher.local_watcher Don't update as in process StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,164 140200533546752 DEBUG nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,164 140200533546752 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f83024f3180>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,164 140200533546752 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/1234abcd
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,164 140200533546752 TRACE nxdrive.engine.dao.sqlite No processor to release with id 140200533546752
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,205 140200533546752 TRACE nxdrive.engine.dao.sqlite Acquired processor 140200533546752 for row 3
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,206 140200533546752 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1, Local state: synchronized, Remote state: synchronized, State: synchronized)(0)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,206 140200533546752 TRACE nxdrive.engine.processor Skip as pair is in non-processable state: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,206 140200533546752 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/1234abcd
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,206 140200533546752 TRACE nxdrive.engine.processor u'/nuxeo drive test workspace/1234abcd'
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,247 140200533546752 TRACE nxdrive.engine.dao.sqlite Released processor 140200533546752
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,247 140200533546752 DEBUG nxdrive.engine.workers Thread LocalFolderProcessor(140200533546752) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,267 140200525154048 DEBUG nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)(0)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,268 140200525154048 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f83024f3510>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,268 140200525154048 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/2345BCDF
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,268 140200525154048 DEBUG nxdrive.engine.workers Increasing error [Can be Office Temp] (None) for StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,305 140200525154048 DEBUG nxdrive.engine.queue_manager Blacklisting pair for 60s: StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,306 140200525154048 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f83024f3510>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,306 140200525154048 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/2345bcdf
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,347 140200525154048 TRACE nxdrive.engine.dao.sqlite Released processor 140200525154048
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,347 140200525154048 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(140200525154048) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,607 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,617 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,617 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD'
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,617 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD'> on known pair: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:04,618 140201760745216 TRACE nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/1234ABCD, remote_ref=defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1]
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,862 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,863 140200550332160 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 2249, 'lastSyncActiveRootDefinitions': u'default:94d55519-a17d-4edc-ae58-18d215879c1b'}}
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,863 140200550332160 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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": 2249, "lastSyncActiveRootDefinitions": "default:94d55519-a17d-4edc-ae58-18d215879c1b"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,876 140200550332160 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":2254,"fileSystemChanges":[{"eventId":"documentCreated","eventDate":1448562063945,"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"creationDate":1448562063945,"creator":"nuxeoDriveTestUser_user_1","folder":true,"parentId":"defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448562063945,"name":"1234ABCD","id":"defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b/defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1","userName":"nuxeoDriveTestUser_user_1"},"docUuid":"ca9a4acb-4a24-4c8a-80b0-f840952163f1","fileSystemItemId":"defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1","fileSystemItemName":"1234ABCD"}],"activeSynchronizationRootDefinitions":"default:94d55519-a17d-4edc-ae58-18d215879c1b","syncDate":1448562065000}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,876 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher 1 remote changes detected
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,876 140200550332160 TRACE nxdrive.engine.watcher.remote_watcher Interacting...
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,877 140200550332160 TRACE nxdrive.engine.watcher.remote_watcher Interacting finished...
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,877 140201963087680 DEBUG nxdrive.tests.common_unit_test Remote changes slot for: 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,877 140200550332160 TRACE nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'1234ABCD', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'lastModificationDate': 1448562063945, u'id': u'defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1', u'canCreateChild': True, u'parentId': u'defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b/defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1', u'folder': True, u'creationDate': 1448562063945, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True}, u'fileSystemItemId': u'defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1', u'fileSystemItemName': u'1234ABCD', u'repositoryId': u'default', u'docUuid': u'ca9a4acb-4a24-4c8a-80b0-f840952163f1', u'eventDate': 1448562063945}
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,878 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/1234ABCD' (force_recursion:0)
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,878 140200550332160 TRACE nxdrive.engine.dao.sqlite Increasing version to 2 for pair RemoteFileInfo(name=u'1234ABCD', uid=u'defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1', parent_uid=u'defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b/defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1', folderish=True, last_modification_time=datetime.datetime(2015, 11, 26, 19, 21, 3), 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)
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,914 140200550332160 TRACE nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,915 140200550332160 TRACE nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:True, State: remotely_modified)
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,915 140200550332160 TRACE nxdrive.engine.queue_manager Pushed to _remote_folder_queue, now of size: 1
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,915 140201963087680 TRACE nxdrive.engine.queue_manager Launching processors
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,915 140201963087680 DEBUG nxdrive.engine.queue_manager creating remote folder processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,916 140200525154048 DEBUG nxdrive.engine.workers Thread RemoteFolderProcessor(140200525154048) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,948 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Remote scanning: /Nuxeo Drive Test Workspace/1234ABCD
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,949 140200550332160 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1'}}
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,949 140200550332160 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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#ca9a4acb-4a24-4c8a-80b0-f840952163f1"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,969 140200550332160 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
19:21:14 [INFO] [exec] 2015-11-26 19:21:05,990 140200525154048 TRACE nxdrive.engine.dao.sqlite Acquired processor 140200525154048 for row 3
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,208 140201963087680 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is active, overall size = 0, empty polls count = 0
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,220 140200525154048 DEBUG nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1, Local state: synchronized, Remote state: modified, State: remotely_modified)(2)
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,220 140200525154048 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f8302493640>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1, Local state: synchronized, Remote state: modified, State: remotely_modified)
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,220 140200525154048 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/1234ABCD
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,221 140200525154048 DEBUG nxdrive.engine.processor No local impact of metadata update on document '1234ABCD'.
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,221 140200525154048 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/1234ABCD, remote_name=1234ABCD, version=2] with version=2 and state=synchronized
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,258 140200525154048 DEBUG nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1, Local state: synchronized, Remote state: modified, State: remotely_modified)'
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,258 140200525154048 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f8302493640>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/1234ABCD', Remote: defaultFileSystemItemFactory#default#ca9a4acb-4a24-4c8a-80b0-f840952163f1, Local state: synchronized, Remote state: modified, State: remotely_modified)
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,258 140200525154048 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/1234abcd
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,258 140200525154048 TRACE nxdrive.engine.dao.sqlite No processor to release with id 140200525154048
19:21:14 [INFO] [exec] 2015-11-26 19:21:06,258 140200525154048 DEBUG nxdrive.engine.workers Thread RemoteFolderProcessor(140200525154048) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:09,259 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
19:21:14 [INFO] [exec] 2015-11-26 19:21:09,259 140200550332160 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 2254, 'lastSyncActiveRootDefinitions': u'default:94d55519-a17d-4edc-ae58-18d215879c1b'}}
19:21:14 [INFO] [exec] 2015-11-26 19:21:09,260 140200550332160 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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": 2254, "lastSyncActiveRootDefinitions": "default:94d55519-a17d-4edc-ae58-18d215879c1b"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:09,270 140200550332160 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":2258,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:94d55519-a17d-4edc-ae58-18d215879c1b","syncDate":1448562069000}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:09,270 140201963087680 TRACE nxdrive.tests.common_unit_test No remote changes slot for: 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:09,367 140201963087680 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
19:21:14 [INFO] [exec] 2015-11-26 19:21:09,400 140201963087680 DEBUG nxdrive.engine.engine Emitting syncCompleted for engine 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:09,401 140201963087680 DEBUG nxdrive.tests.common_unit_test Sync Completed slot for: 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:10,301 140201752352512 DEBUG nxdrive.tests.common_unit_test Sync completed, ended wait for sync
19:21:14 [INFO] [exec] 2015-11-26 19:21:10,301 140201752352512 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'query': u"SELECT * FROM Document WHERE ecm:parentId = '94d55519-a17d-4edc-ae58-18d215879c1b' AND ecm:primaryType IN ('File', 'Workspace', 'Folder') AND ecm:currentLifeCycleState != 'deleted' ORDER BY dc:title, dc:created LIMIT 1000"}}
19:21:14 [INFO] [exec] 2015-11-26 19:21:10,301 140201752352512 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjMjFkMzA='}, cookies [] and JSON payload '{"params": {"query": "SELECT * FROM Document WHERE ecm:parentId = \'94d55519-a17d-4edc-ae58-18d215879c1b\' AND ecm:primaryType IN (\'File\', \'Workspace\', \'Folder\') AND ecm:currentLifeCycleState != \'deleted\' ORDER BY dc:title, dc:created LIMIT 1000"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:10,323 140201752352512 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":"ca9a4acb-4a24-4c8a-80b0-f840952163f1","path":"/default-domain/workspaces/nuxeo-drive-test-workspace/1234ABCD","type":"Folder","state":"project","parentRef":"94d55519-a17d-4edc-ae58-18d215879c1b","isCheckedOut":true,"changeToken":"1448562063945","title":"1234ABCD","lastModified":"2015-11-26T18:21:03.94Z","properties":{"common:size":null,"common:icon-expanded":null,"common:icon":"/icons/folder.gif","dc:description":null,"dc:language":null,"dc:coverage":null,"dc:valid":null,"dc:creator":"nuxeoDriveTestUser_user_1","dc:modified":"2015-11-26T18:21:03.94Z","dc:lastContributor":"nuxeoDriveTestUser_user_1","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-26T18:21:03.94Z","dc:title":"1234ABCD","dc:issued":null,"dc:nature":null,"dc:subjects":[],"dc:contributors":["nuxeoDriveTestUser_user_1"],"dc:source":null,"dc:publisher":null},"facets":["Folderish"]}]}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:10,323 140201752352512 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
19:21:14 [INFO] [exec] 2015-11-26 19:21:10,324 140201752352512 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTpjMjFkMzA='}, cookies [] and JSON payload '{"params": {"value": "/default-domain/workspaces/nuxeo-drive-test-workspace"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:10,340 140201752352512 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"94d55519-a17d-4edc-ae58-18d215879c1b","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"42d51920-5947-4c53-ac87-ca4804ddb3fa","isCheckedOut":true,"changeToken":"1448562057244","title":"Nuxeo Drive Test Workspace","lastModified":"2015-11-26T18:20:57.24Z","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-26T18:20:57.24Z","dc:lastContributor":"nuxeoDriveTestUser_user_2","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-11-26T18:20:55.76Z","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-26T18:20:57.20Z","enabled":true,"username":"nuxeoDriveTestUser_user_1"},{"lastChangeDate":"2015-11-26T18:20:57.24Z","enabled":true,"username":"nuxeoDriveTestUser_user_2"}],"publish:sections":[]},"facets":["DriveSynchronized","Folderish","SuperSpace"]}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:10,341 140201752352512 DEBUG nxdrive.tests.common_unit_test Wait for sync
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,306 140201963087680 DEBUG nxdrive.engine.queue_manager End of blacklist period, pushing doc_pair: StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,307 140201963087680 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:0, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,307 140201963087680 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,307 140201963087680 TRACE nxdrive.engine.queue_manager Launching processors
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,307 140201963087680 DEBUG nxdrive.engine.queue_manager creating local file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,308 140201963087680 DEBUG nxdrive.engine.queue_manager creating additional file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,308 140200525154048 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(140200525154048) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,309 140201963087680 DEBUG nxdrive.engine.queue_manager creating additional file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,309 140200533546752 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200533546752) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,309 140200533546752 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200533546752) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,310 140201963087680 DEBUG nxdrive.engine.queue_manager creating additional file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,310 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,311 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,311 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,311 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,417 140200525154048 TRACE nxdrive.engine.dao.sqlite Acquired processor 140200525154048 for row 4
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,418 140200525154048 DEBUG nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)(0)
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,419 140200525154048 TRACE nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f83024938a0>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,419 140200525154048 TRACE nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/2345BCDF
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,419 140200525154048 TRACE nxdrive.engine.processor Entered _synchronize_locally_created, parent_pair = StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,420 140200525154048 DEBUG nxdrive.engine.processor Creating remote document '2345BCDF' in folder 'Nuxeo Drive Test Workspace'
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,426 140200525154048 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-aa776398-3834-4d9d-ad58-ca3bab730941"}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,426 140200525154048 TRACE nxdrive.utils Could not guess mime type for '2345BCDF', returing 'application/octet-stream'
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,427 140200525154048 TRACE nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 4096 bytes
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,427 140200525154048 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-aa776398-3834-4d9d-ad58-ca3bab730941/0 with headers {'Content-Length': 4, 'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', 'X-File-Type': 'application/octet-stream', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 4, 'Cache-Control': 'no-cache', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': '2345BCDF', 'X-Client-Version': '2.0-dev'} and cookies [] for file /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,433 140200525154048 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-aa776398-3834-4d9d-ad58-ca3bab730941/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"4","uploadType":"normal","batchId":"batchId-aa776398-3834-4d9d-ad58-ca3bab730941"}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,433 140200525154048 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 /home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,433 140200525154048 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b'}}
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,434 140200525154048 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-aa776398-3834-4d9d-ad58-ca3bab730941/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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#94d55519-a17d-4edc-ae58-18d215879c1b"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,746 140200525154048 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-aa776398-3834-4d9d-ad58-ca3bab730941/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digestAlgorithm":"MD5","canUpdate":true,"downloadURL":"nxfile/default/ca2674d5-9d5f-4ce2-84af-cde6c891c7e6/blobholder:0/2345BCDF.txt","digest":"098f6bcd4621d373cade4e832627b4f6","creationDate":1448562071664,"creator":"nuxeoDriveTestUser_user_1","folder":false,"parentId":"defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b","canRename":true,"canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1448562071664,"name":"2345BCDF.txt","id":"defaultFileSystemItemFactory#default#ca2674d5-9d5f-4ce2-84af-cde6c891c7e6","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#94d55519-a17d-4edc-ae58-18d215879c1b/defaultFileSystemItemFactory#default#ca2674d5-9d5f-4ce2-84af-cde6c891c7e6","userName":"nuxeoDriveTestUser_user_1"}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,776 140200525154048 TRACE nxdrive.engine.processor Transfer speed 0 ko/s
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,810 140200525154048 TRACE nxdrive.engine.dao.sqlite Push to queue: locally_created: None
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,810 140200525154048 TRACE nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:False, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,810 140200525154048 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,810 140200525154048 TRACE nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#ca2674d5-9d5f-4ce2-84af-cde6c891c7e6
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,811 140201963087680 TRACE nxdrive.engine.queue_manager Launching processors
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,811 140200525154048 TRACE nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#ca2674d5-9d5f-4ce2-84af-cde6c891c7e6' on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,812 140201963087680 DEBUG nxdrive.engine.queue_manager creating additional file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,812 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF, wd=2, mask=IN_ATTRIB, cookie=0, name=2345BCDF>
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,813 140200634193664 DEBUG watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF, wd=2, mask=IN_ATTRIB, cookie=0, name=2345BCDF>
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,813 140200525154048 TRACE nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/2345BCDF, remote_name=None, version=0] with version=0 and state=synchronized
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,814 140201963087680 DEBUG nxdrive.engine.queue_manager creating additional file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,814 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,815 140201963087680 DEBUG nxdrive.engine.queue_manager creating additional file processor
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,815 140200533546752 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200533546752) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,816 140200533546752 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200533546752) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,816 140200508368640 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200508368640) start
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,816 140200508368640 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200508368640) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,852 140200525154048 TRACE nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f83024938a0>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,852 140200525154048 TRACE nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/2345bcdf
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,885 140200516761344 TRACE nxdrive.engine.dao.sqlite Acquired processor 140200516761344 for row 4
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,886 140200525154048 TRACE nxdrive.engine.dao.sqlite No processor to release with id 140200525154048
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,886 140200525154048 DEBUG nxdrive.engine.workers Thread LocalFileProcessor(140200525154048) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,886 140200516761344 DEBUG nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: defaultFileSystemItemFactory#default#ca2674d5-9d5f-4ce2-84af-cde6c891c7e6, Local state: synchronized, Remote state: synchronized, State: synchronized)(0)
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,886 140200516761344 TRACE nxdrive.engine.processor Skip as pair is in non-processable state: StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: defaultFileSystemItemFactory#default#ca2674d5-9d5f-4ce2-84af-cde6c891c7e6, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,919 140200516761344 TRACE nxdrive.engine.dao.sqlite Released processor 140200516761344
19:21:14 [INFO] [exec] 2015-11-26 19:21:11,919 140200516761344 DEBUG nxdrive.engine.workers Thread GenericProcessor(140200516761344) end
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,323 140200664622848 TRACE nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,325 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'>
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,325 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,326 140201760745216 TRACE nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/home/hudson/tmp/workspace/FT-nuxeo-drive-master-linux/tmp/tmpWiGnWl-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/2345BCDF'> on known pair: StateRow[4](Local: u'/Nuxeo Drive Test Workspace/2345BCDF', Remote: defaultFileSystemItemFactory#default#ca2674d5-9d5f-4ce2-84af-cde6c891c7e6, Local state: synchronized, Remote state: synchronized, State: synchronized)
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,327 140201760745216 DEBUG nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/2345BCDF
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,416 140200550332160 DEBUG nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,416 140200550332160 TRACE nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 2258, 'lastSyncActiveRootDefinitions': u'default:94d55519-a17d-4edc-ae58-18d215879c1b'}}
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,416 140200550332160 TRACE nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': 'de099c19-ed99-43ee-9fb2-c8957ca18dc1', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f0236c2946a11e5b009d067e5f2a1a2', '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": 2258, "lastSyncActiveRootDefinitions": "default:94d55519-a17d-4edc-ae58-18d215879c1b"}}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,428 140200550332160 TRACE nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":2265,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:94d55519-a17d-4edc-ae58-18d215879c1b","syncDate":1448562072000}'
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,428 140201963087680 TRACE nxdrive.tests.common_unit_test No remote changes slot for: 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,503 140201963087680 DEBUG nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 2
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,528 140201963087680 DEBUG nxdrive.engine.engine Emitting syncCompleted for engine 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:12,528 140201963087680 DEBUG nxdrive.tests.common_unit_test Sync Completed slot for: 6f37df8e946a11e5b009d067e5f2a1a2
19:21:14 [INFO] [exec] 2015-11-26 19:21:13,344 140201752352512 DEBUG nxdrive.tests.common_unit_test Sync completed, ended wait for sync
19:21:14 [INFO] [exec] --------------------- >> end captured logging << ---------------------
- depends on
-
NXDRIVE-460 Some unwanted files are created during the synchronisation process
-
- Resolved
-
