[NXDRIVE-504] Random failure under Linux / OS X at line 222, in test_watchdog_encoding - Nuxeo Issue Tracker

XML

Word

Printable

Details

Type: Bug
Status: Resolved
Priority: Minor
Resolution: Cannot Reproduce
Affects Version/s: None
Fix Version/s: 2.1.120
Component/s: Tests, Watchdog

Sprint:
drive-8.1-1, drive-8.1-2, drive-8.1-3

Description

06:22:24 [INFO]      [exec] ======================================================================
06:22:24 [INFO]      [exec] FAIL: test_watchdog_encoding (nxdrive.tests.test_watchers.TestWatchers)
06:22:24 [INFO]      [exec] ----------------------------------------------------------------------
06:22:24 [INFO]      [exec] Traceback (most recent call last):
06:22:24 [INFO]      [exec]   File "/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/tests/test_watchers.py", line 222, in test_watchdog_encoding
06:22:24 [INFO]      [exec]     self.wait_sync()
06:22:24 [INFO]      [exec]   File "/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/tests/common_unit_test.py", line 353, in wait_sync
06:22:24 [INFO]      [exec]     self.fail("Wait for sync timeout expired")
06:22:24 [INFO]      [exec] AssertionError: Wait for sync timeout expired
06:22:24 [INFO]      [exec] -------------------- >> begin captured logging << --------------------
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,402 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Create DAO on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,403 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Create main connexion on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,437 140009472325440 DEBUG    nxdrive.osi        Not using any OS integration
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,440 140009472325440 DEBUG    nxdrive.updater    Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,445 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Create DAO on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmp0iqmVO-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,445 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Create main connexion on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmp0iqmVO-nxdrive-tests-user-2/nuxeo-drive-conf/manager.db (dir exists: 1 / file exists: 0)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,453 140009472325440 DEBUG    nxdrive.osi        Not using any OS integration
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,459 140009472325440 DEBUG    nxdrive.updater    Application is not frozen, cannot build Esky instance, as a consequence update features won't be available
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,460 140009472325440 DEBUG    nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,460 140009472325440 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 []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,476 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,477 140009472325440 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": "/"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,480 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"3c2312ff-4d20-43a8-94e3-1ed16c0b7991","path":"/","type":"Root","state":null,"parentRef":"/","isCheckedOut":true,"changeToken":null,"title":"3c2312ff-4d20-43a8-94e3-1ed16c0b7991","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"]}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,480 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'userNames': 'user_1, user_2', 'permission': 'ReadWrite'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,481 140009472325440 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"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,509 140009472325440 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'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,527 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Create DAO on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_6f9184ea9ca211e5a99c0242ac110003.db
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,528 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Create main connexion on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/nuxeo-drive-conf/ndrive_6f9184ea9ca211e5a99c0242ac110003.db (dir exists: 1 / file exists: 0)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,543 140009472325440 TRACE    nxdrive.engine.dao.sqlite Vacuum sqlite
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,548 140009472325440 TRACE    nxdrive.engine.dao.sqlite Vacuum sqlite finished
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,549 140009472325440 DEBUG    nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,549 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTowMzJhMjk='} and cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,566 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Linux+Desktop&revoke=false&deviceId=6f8688609ca211e5a99c0242ac110003&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTowMzJhMjk='} and cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,575 140009472325440 TRACE    nxdrive.client.base_automation_client Got token '7a72b764-42cd-4a41-b38b-963da5b3bb9a' with cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,580 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,581 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": {}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,584 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"updateSiteURL":"http://community.nuxeo.com/static/drive/","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/","serverVersion":"8.1-SNAPSHOT"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,584 140009472325440 DEBUG    nxdrive.engine.engine Fetched update info for engine [localhost] from server http://localhost:8080/nuxeo/: {u'betaUpdateSiteURL': u'http://community.nuxeo.com/static/drive-tests/', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/', u'serverVersion': u'8.1-SNAPSHOT'}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,590 140009472325440 DEBUG    nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,590 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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 []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,603 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,603 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": {}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,607 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"creationDate":606,"creator":"system","folder":true,"parentId":null,"canDelete":false,"lastContributor":"system","lastModificationDate":606,"canRename":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_1"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,608 140009472325440 TRACE    nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,615 140009472325440 TRACE    nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,616 140009472325440 TRACE    nxdrive.client.local_client Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_1|6f8688609ca211e5a99c0242ac110003|6f9184ea9ca211e5a99c0242ac110003' on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,616 140009472325440 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,620 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[1](Local: u'/', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,629 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Create DAO on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmp0iqmVO-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_6fa3157a9ca211e5a99c0242ac110003.db
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,629 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Create main connexion on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmp0iqmVO-nxdrive-tests-user-2/nuxeo-drive-conf/ndrive_6fa3157a9ca211e5a99c0242ac110003.db (dir exists: 1 / file exists: 0)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,640 140009472325440 TRACE    nxdrive.engine.dao.sqlite Vacuum sqlite
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,644 140009472325440 TRACE    nxdrive.engine.dao.sqlite Vacuum sqlite finished
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,646 140009472325440 DEBUG    nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,646 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6f88e8769ca211e5a99c0242ac110003', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo5Yjk1OWE='} and cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,692 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/authentication/token?applicationName=Nuxeo+Drive&deviceDescription=Linux+Desktop&revoke=false&deviceId=6f88e8769ca211e5a99c0242ac110003&permission=ReadWrite with headers {'X-Client-Version': '2.0-dev', 'X-Device-Id': '6f88e8769ca211e5a99c0242ac110003', '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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo5Yjk1OWE='} and cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,703 140009472325440 TRACE    nxdrive.client.base_automation_client Got token 'c336ab11-2cb7-418b-bc91-474e84288fe3' with cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,709 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,709 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo with headers {'X-Authentication-Token': 'c336ab11-2cb7-418b-bc91-474e84288fe3', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f88e8769ca211e5a99c0242ac110003', '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": {}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,711 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetClientUpdateInfo' with cookies []: '{"updateSiteURL":"http://community.nuxeo.com/static/drive/","betaUpdateSiteURL":"http://community.nuxeo.com/static/drive-tests/","serverVersion":"8.1-SNAPSHOT"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,712 140009472325440 DEBUG    nxdrive.engine.engine Fetched update info for engine [localhost] from server http://localhost:8080/nuxeo/: {u'betaUpdateSiteURL': u'http://community.nuxeo.com/static/drive-tests/', u'updateSiteURL': u'http://community.nuxeo.com/static/drive/', u'serverVersion': u'8.1-SNAPSHOT'}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,716 140009472325440 DEBUG    nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,717 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/ with headers {'X-Authentication-Token': 'c336ab11-2cb7-418b-bc91-474e84288fe3', 'X-Device-Id': '6f88e8769ca211e5a99c0242ac110003', '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 []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,729 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,729 140009472325440 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder with headers {'X-Authentication-Token': 'c336ab11-2cb7-418b-bc91-474e84288fe3', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f88e8769ca211e5a99c0242ac110003', '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": {}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,732 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetTopLevelFolder' with cookies []: '{"canCreateChild":false,"creationDate":731,"creator":"system","folder":true,"parentId":null,"canDelete":false,"lastContributor":"system","lastModificationDate":731,"canRename":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_2"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,732 140009472325440 TRACE    nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,736 140009472325440 TRACE    nxdrive.engine.dao.sqlite Will not push pair: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,737 140009472325440 TRACE    nxdrive.client.local_client Setting xattr ndriveroot with value u'http://localhost:8080/nuxeo/|nuxeoDriveTestUser_user_2|6f88e8769ca211e5a99c0242ac110003|6fa3157a9ca211e5a99c0242ac110003' on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmp0iqmVO-nxdrive-tests-user-2/Nuxeo Drive'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,737 140009472325440 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/, remote_name=None, version=0] with version=0
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,738 140009472325440 DEBUG    nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[1](Local: u'/', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,740 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'/default-domain/workspaces/nuxeo-drive-test-workspace'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,741 140009472325440 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"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,747 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"715d569b-89c4-43b3-b66b-781cd14ff53c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"5aa6983a-eac9-48e3-bc83-3dd5d28e366a","isCheckedOut":true,"changeToken":"1449465717490","title":"Nuxeo Drive Test Workspace","lastModified":"2015-12-07T05:21:57.49Z","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-12-07T05:21:57.49Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-12-07T05:21:57.49Z","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"]}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,748 140009472325440 DEBUG    nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,748 140009472325440 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTowMzJhMjk='} and cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,762 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,762 140009472325440 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTowMzJhMjk='}, cookies [] and JSON payload '{"params": {"value": "715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,766 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"715d569b-89c4-43b3-b66b-781cd14ff53c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"5aa6983a-eac9-48e3-bc83-3dd5d28e366a","isCheckedOut":true,"changeToken":"1449465717490","title":"Nuxeo Drive Test Workspace","lastModified":"2015-12-07T05:21:57.49Z","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-12-07T05:21:57.49Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-12-07T05:21:57.49Z","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"]}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,767 140009472325440 DEBUG    nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,767 140009472325440 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo5Yjk1OWE='} and cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,782 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'value': u'715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,782 140009472325440 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo5Yjk1OWE='}, cookies [] and JSON payload '{"params": {"value": "715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,786 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/Document.Fetch' with cookies []: '{"entity-type":"document","repository":"default","uid":"715d569b-89c4-43b3-b66b-781cd14ff53c","path":"/default-domain/workspaces/nuxeo-drive-test-workspace","type":"Workspace","state":"project","parentRef":"5aa6983a-eac9-48e3-bc83-3dd5d28e366a","isCheckedOut":true,"changeToken":"1449465717490","title":"Nuxeo Drive Test Workspace","lastModified":"2015-12-07T05:21:57.49Z","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-12-07T05:21:57.49Z","dc:lastContributor":"Administrator","dc:rights":null,"dc:expired":null,"dc:format":null,"dc:created":"2015-12-07T05:21:57.49Z","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"]}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,787 140009472325440 DEBUG    nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,787 140009472325440 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTowMzJhMjk='} and cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,802 140009472325440 DEBUG    nxdrive.client.base_automation_client Proxy configuration: System, effective proxy list: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,803 140009472325440 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo5Yjk1OWE='} and cookies []
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,818 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'input': u'doc:715d569b-89c4-43b3-b66b-781cd14ff53c', 'params': {'enable': True}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,818 140009472325440 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMTowMzJhMjk='}, cookies [] and JSON payload '{"input": "doc:715d569b-89c4-43b3-b66b-781cd14ff53c", "params": {"enable": true}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,840 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,840 140009472325440 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'input': u'doc:715d569b-89c4-43b3-b66b-781cd14ff53c', 'params': {'enable': True}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,841 140009472325440 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 bnV4ZW9Ecml2ZVRlc3RVc2VyX3VzZXJfMjo5Yjk1OWE='}, cookies [] and JSON payload '{"input": "doc:715d569b-89c4-43b3-b66b-781cd14ff53c", "params": {"enable": true}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,859 140009472325440 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.SetSynchronization' with cookies [] has content-type ''
06:22:24 [INFO]      [exec] 2015-12-07 05:21:57,859 140009195947776 DEBUG    nxdrive.tests.common_unit_test UnitTest thread started
06:22:24 [INFO]      [exec] 2015-12-07 05:21:58,861 140009195947776 TRACE    nxdrive.client.local_client Setting xattr drive-fs-test with value 'NXDRIVE_VERIFICATION' on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:58,862 140009195947776 TRACE    nxdrive.client.local_client Removing xattr drive-fs-test from /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive
06:22:24 [INFO]      [exec] 2015-12-07 05:21:58,862 140009195947776 DEBUG    nxdrive.engine.engine Engine start
06:22:24 [INFO]      [exec] 2015-12-07 05:21:58,863 140009195947776 DEBUG    nxdrive.tests.common_unit_test Wait for sync
06:22:24 [INFO]      [exec] 2015-12-07 05:21:58,863 140006829958912 DEBUG    nxdrive.engine.workers Thread LocalWatcher(140006829958912) start
06:22:24 [INFO]      [exec] 2015-12-07 05:21:58,863 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Watching FS modification on : /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive
06:22:24 [INFO]      [exec] 2015-12-07 05:21:58,865 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:58,866 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup, wd=1, mask=IN_CREATE, cookie=0, name=.watchdog_setup>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:58,867 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup, wd=1, mask=IN_ATTRIB, cookie=0, name=.watchdog_setup>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,379 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,379 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,379 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,380 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,868 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup, wd=1, mask=IN_DELETE, cookie=0, name=.watchdog_setup>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,869 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,870 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Watchdog setup finished
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,871 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Full scan started
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,871 140006829958912 DEBUG    nxdrive.engine.queue_manager Suspending queue
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,871 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Starting recursive local scan of u'/'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,872 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Starting to get DB local children for u'/'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,872 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Fetched DB local children for u'/'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,873 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Starting to get FS children info for u'/'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,873 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Fetched FS children info for u'/'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,873 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Ended recursive local scan of u'/'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,873 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Full scan finished in 3ms
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,873 140006829958912 DEBUG    nxdrive.engine.queue_manager Resuming queue
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,874 140006706169600 DEBUG    nxdrive.engine.workers Thread RemoteWatcher(140006706169600) start
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,875 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=True
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,875 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Remote full scan
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,875 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,875 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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#"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,879 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with cookies []: '{"canCreateChild":false,"creationDate":878,"creator":"system","folder":true,"parentId":null,"canDelete":false,"lastContributor":"system","lastModificationDate":878,"canRename":false,"name":"Nuxeo Drive","id":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","userName":"nuxeoDriveTestUser_user_1"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,879 140006706169600 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, 0, 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)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,884 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,884 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,884 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,885 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,887 140006706169600 TRACE    nxdrive.engine.dao.sqlite Will not push pair: synchronized: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,887 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,887 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": {}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,888 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,888 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,889 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,889 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,910 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":13820,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:715d569b-89c4-43b3-b66b-781cd14ff53c","syncDate":1449465719000}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,919 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Remote scanning: /
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,920 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,920 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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#"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,926 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"canCreateChild":true,"creationDate":1449465717490,"creator":"Administrator","folder":true,"parentId":"org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_2","lastModificationDate":1449465717851,"canRename":true,"name":"Nuxeo Drive Test Workspace","id":"defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","userName":"nuxeoDriveTestUser_user_1"}]'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,926 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Scanning remote child: RemoteFileInfo(name=u'Nuxeo Drive Test Workspace', uid=u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', parent_uid=u'org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', folderish=True, last_modification_time=datetime.datetime(2015, 12, 7, 5, 21, 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)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,928 140006706169600 TRACE    nxdrive.engine.dao.sqlite Push to queue: remotely_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,928 140006706169600 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[2](Folderish:True, State: remotely_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,928 140006706169600 TRACE    nxdrive.engine.queue_manager Pushed to _remote_folder_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,929 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Remote scanning: /Nuxeo Drive Test Workspace
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,929 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,929 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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#715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,940 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,948 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Remote scan finished in 74ms
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,948 140009472325440 DEBUG    nxdrive.tests.common_unit_test Remote scan completed for engine 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,949 140009472325440 TRACE    nxdrive.engine.queue_manager Init processors
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,951 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,952 140009472325440 DEBUG    nxdrive.engine.queue_manager creating remote folder processor
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,953 140006605715200 DEBUG    nxdrive.engine.workers Thread RemoteFolderProcessor(140006605715200) start
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,954 140006605715200 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006605715200 for row 2
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,954 140006605715200 DEBUG    nxdrive.engine.processor Executing processor on StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: unknown, Remote state: created, State: remotely_created)(0)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,955 140006605715200 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f55dc6418a0>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: unknown, Remote state: created, State: remotely_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,955 140006605715200 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,956 140006605715200 TRACE    nxdrive.engine.processor readonly unlock: unlock on / with 1
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,956 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,957 140006605715200 DEBUG    nxdrive.engine.processor Creating local folder 'Nuxeo Drive Test Workspace' in '/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,958 140006714562304 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Nuxeo Drive>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,959 140006605715200 TRACE    nxdrive.engine.processor readonly lock: update lock count on / to 0
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,959 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=1, mask=IN_CREATE|IN_ISDIR, cookie=0, name=Nuxeo Drive Test Workspace>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,960 140006714562304 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Nuxeo Drive>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,961 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,961 140006605715200 TRACE    nxdrive.engine.processor readonly lock: relocked path: / with 1
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,961 140006605715200 TRACE    nxdrive.client.local_client Setting xattr ndrive with value u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c' on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,962 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Nuxeo Drive Test Workspace>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,962 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,962 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=1, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Nuxeo Drive Test Workspace>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,963 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,965 140006605715200 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
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,969 140006605715200 DEBUG    nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: unknown, Remote state: created, State: remotely_created)'
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,969 140006605715200 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_created of <nxdrive.engine.processor.Processor object at 0x7f55dc6418a0>> on doc pair StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: unknown, Remote state: created, State: remotely_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,969 140006605715200 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,970 140006605715200 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006605715200
06:22:24 [INFO]      [exec] 2015-12-07 05:21:59,970 140006605715200 DEBUG    nxdrive.engine.workers Thread RemoteFolderProcessor(140006605715200) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,380 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileDeletedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,380 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,387 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileDeletedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,387 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [deleted] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/.watchdog_setup'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,387 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,388 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,485 140006689384192 TRACE    nxdrive.engine.watcher.local_watcher DriveFSROOT: Nuxeo Drive : need: Nuxeo Drive
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,494 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,494 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,495 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,495 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,499 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,499 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,500 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,500 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,500 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,501 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher This should only happen in case of a quick move and copy-paste
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,501 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,501 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,501 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,501 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,502 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:00,503 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:02,989 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
06:22:24 [INFO]      [exec] 2015-12-07 05:22:02,989 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 13820, 'lastSyncActiveRootDefinitions': u'default:715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:02,990 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": 13820, "lastSyncActiveRootDefinitions": "default:715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,000 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":13828,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:715d569b-89c4-43b3-b66b-781cd14ff53c","syncDate":1449465722000}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,000 140009472325440 TRACE    nxdrive.tests.common_unit_test No remote changes slot for: 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,169 140009472325440 DEBUG    nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 0, empty polls count = 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,171 140009472325440 DEBUG    nxdrive.engine.engine Emitting syncCompleted for engine 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,171 140009472325440 DEBUG    nxdrive.tests.common_unit_test Sync Completed slot for: 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,868 140009195947776 DEBUG    nxdrive.tests.common_unit_test Sync completed, ended wait for sync
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,869 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt, wd=2, mask=IN_CREATE, cookie=0, name=Accentué.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,870 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt, wd=2, mask=IN_MODIFY, cookie=0, name=Accentué.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,872 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Pôle applicatif, wd=2, mask=IN_CREATE|IN_ISDIR, cookie=0, name=Pôle applicatif>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,873 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder, wd=2, mask=IN_CREATE|IN_ISDIR, cookie=0, name=Sub folder>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,875 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt, wd=4, mask=IN_CREATE, cookie=0, name=être ou ne pas être.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,875 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt, wd=4, mask=IN_MODIFY, cookie=0, name=être ou ne pas être.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,877 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt, wd=2, mask=IN_CREATE, cookie=0, name=No special character.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,877 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt, wd=2, mask=IN_MODIFY, cookie=0, name=No special character.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:03,878 140009195947776 DEBUG    nxdrive.tests.common_unit_test Wait for sync
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,410 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,411 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,411 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,411 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/P\xf4le applicatif'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,411 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,412 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,412 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,412 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,412 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,412 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,412 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,413 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,413 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,422 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,422 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,422 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Forcing normalization of u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt' to u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,423 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt, wd=2, mask=IN_MOVED_FROM, cookie=93855784, name=Accentué.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,423 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt, wd=2, mask=IN_MOVED_TO, cookie=93855784, name=Accentué.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,425 140006829958912 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,425 140006829958912 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:False, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,425 140006829958912 TRACE    nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,425 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,426 140009472325440 DEBUG    nxdrive.engine.queue_manager creating local file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,426 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,426 140006605715200 DEBUG    nxdrive.engine.workers Thread LocalFileProcessor(140006605715200) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,427 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,427 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,428 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,428 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,428 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,428 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,429 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,431 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,464 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,464 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,464 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,465 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 2 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,466 140006605715200 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006605715200 for row 3
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,471 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,471 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,471 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt'> on known pair: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,471 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Don't update as in process StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,471 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/P\xf4le applicatif'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,472 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/P\xf4le applicatif'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,473 140006829958912 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,473 140006829958912 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:True, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,473 140006829958912 TRACE    nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,473 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,473 140009472325440 DEBUG    nxdrive.engine.queue_manager creating local folder processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,475 140006829958912 DEBUG    nxdrive.engine.queue_manager Suspending queue
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,475 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Starting recursive local scan of u'/Nuxeo Drive Test Workspace/P\xf4le applicatif'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,475 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Starting to get DB local children for u'/Nuxeo Drive Test Workspace/P\xf4le applicatif'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,475 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Fetched DB local children for u'/Nuxeo Drive Test Workspace/P\xf4le applicatif'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,475 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Starting to get FS children info for u'/Nuxeo Drive Test Workspace/P\xf4le applicatif'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,475 140006597322496 DEBUG    nxdrive.engine.workers Thread LocalFolderProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,476 140006605715200 DEBUG    nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)(0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,477 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Fetched FS children info for u'/Nuxeo Drive Test Workspace/P\xf4le applicatif'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,477 140006605715200 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dc641b98>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,477 140006605715200 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Accentué.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,478 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Ended recursive local scan of u'/Nuxeo Drive Test Workspace/P\xf4le applicatif'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,478 140006829958912 DEBUG    nxdrive.engine.queue_manager Resuming queue
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,478 140006597322496 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006597322496 for row 4
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,478 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,478 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,479 140006605715200 TRACE    nxdrive.engine.processor Entered _synchronize_locally_created, parent_pair = StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,479 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,479 140006605715200 DEBUG    nxdrive.engine.processor Creating remote document 'Accentué.odt' in folder 'Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,480 140006597322496 DEBUG    nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/P\xf4le applicatif', Remote: None, Local state: created, Remote state: unknown, State: locally_created)(0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,481 140006597322496 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dbd6e478>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/P\xf4le applicatif', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,481 140006597322496 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Pôle applicatif
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,482 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 3 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,485 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,485 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,486 140006597322496 TRACE    nxdrive.engine.processor Entered _synchronize_locally_created, parent_pair = StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,486 140006597322496 DEBUG    nxdrive.engine.processor Creating remote folder 'Pôle applicatif' in folder 'Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,486 140006597322496 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'name': u'P\xf4le applicatif', 'parentId': u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,487 140006597322496 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": "P\\u00f4le applicatif", "parentId": "defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,488 140006829958912 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,488 140006829958912 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[5](Folderish:True, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,489 140006829958912 TRACE    nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,489 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,489 140006605715200 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-45dd0d69-c580-4ba8-83a1-bb561a0605b2"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,490 140006605715200 TRACE    nxdrive.utils      Guessed mime type 'application/vnd.oasis.opendocument.text' for 'Accentué.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,490 140006605715200 TRACE    nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 4096 bytes
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,490 140006605715200 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-45dd0d69-c580-4ba8-83a1-bb561a0605b2/0 with headers {'Content-Length': 7, 'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 7, 'Cache-Control': 'no-cache', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'Accentu%C3%A9.odt', 'X-Client-Version': '2.0-dev'} and cookies [] for file /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,492 140006829958912 DEBUG    nxdrive.engine.queue_manager Suspending queue
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,492 140006829958912 TRACE    nxdrive.engine.queue_manager Worker({'action': _synchronize_locally_created, 'thread_id': 140006597322496, 'name': 'LocalFolderProcessor'}) is processing: /
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,494 140006605715200 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-45dd0d69-c580-4ba8-83a1-bb561a0605b2/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"7","uploadType":"normal","batchId":"batchId-45dd0d69-c580-4ba8-83a1-bb561a0605b2"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,495 140006605715200 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 /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,495 140006605715200 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,496 140006605715200 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-45dd0d69-c580-4ba8-83a1-bb561a0605b2/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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#715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,493 140006829958912 ERROR    nxdrive.engine.watcher.local_watcher Watchdog exception
06:22:24 [INFO]      [exec] Traceback (most recent call last):
06:22:24 [INFO]      [exec]   File "/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/engine/watcher/local_watcher.py", line 800, in handle_watchdog_event
06:22:24 [INFO]      [exec]     self.scan_pair(rel_path)
06:22:24 [INFO]      [exec]   File "/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/engine/watcher/local_watcher.py", line 255, in scan_pair
06:22:24 [INFO]      [exec]     self._suspend_queue()
06:22:24 [INFO]      [exec]   File "/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/engine/watcher/local_watcher.py", line 249, in _suspend_queue
06:22:24 [INFO]      [exec]     for processor in self._engine.get_queue_manager().get_processors_on('/', exact_match=False):
06:22:24 [INFO]      [exec]   File "/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/engine/queue_manager.py", line 412, in get_processors_on
06:22:24 [INFO]      [exec]     if self.is_processing_file(self._local_file_thread.worker, path, exact_match):
06:22:24 [INFO]      [exec]   File "/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/engine/queue_manager.py", line 396, in is_processing_file
06:22:24 [INFO]      [exec]     log.trace("Worker(%r) is processing: %s", worker.get_metrics(), path)
06:22:24 [INFO]      [exec]   File "/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/nuxeo-drive-client/nxdrive/logging_config.py", line 142, in <lambda>
06:22:24 [INFO]      [exec]     trace = lambda *args, **kwargs: logger.log(TRACE, *args, **kwargs)
06:22:24 [INFO]      [exec]   File "/usr/lib/python2.7/logging/__init__.py", line 1216, in log
06:22:24 [INFO]      [exec]     self._log(level, msg, args, **kwargs)
06:22:24 [INFO]      [exec]   File "/usr/lib/python2.7/logging/__init__.py", line 1271, in _log
06:22:24 [INFO]      [exec]     self.handle(record)
06:22:24 [INFO]      [exec]   File "/usr/lib/python2.7/logging/__init__.py", line 1281, in handle
06:22:24 [INFO]      [exec]     self.callHandlers(record)
06:22:24 [INFO]      [exec]   File "/usr/lib/python2.7/logging/__init__.py", line 1321, in callHandlers
06:22:24 [INFO]      [exec]     hdlr.handle(record)
06:22:24 [INFO]      [exec]   File "/usr/lib/python2.7/logging/__init__.py", line 749, in handle
06:22:24 [INFO]      [exec]     self.emit(record)
06:22:24 [INFO]      [exec]   File "/opt/jenkins/.local/lib/python2.7/site-packages/nose/plugins/logcapture.py", line 82, in emit
06:22:24 [INFO]      [exec]     self.buffer.append(self.format(record))
06:22:24 [INFO]      [exec]   File "/usr/lib/python2.7/logging/__init__.py", line 724, in format
06:22:24 [INFO]      [exec]     return fmt.format(record)
06:22:24 [INFO]      [exec]   File "/usr/lib/python2.7/logging/__init__.py", line 464, in format
06:22:24 [INFO]      [exec]     record.message = record.getMessage()
06:22:24 [INFO]      [exec]   File "/usr/lib/python2.7/logging/__init__.py", line 328, in getMessage
06:22:24 [INFO]      [exec]     msg = msg % self.args
06:22:24 [INFO]      [exec] UnicodeEncodeError: 'ascii' codec can't encode character u'\xe9' in position 14: ordinal not in range(128)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,497 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,497 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,498 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,498 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 4 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,500 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,500 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,500 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Forcing normalization of u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt' to u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,501 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt, wd=4, mask=IN_MOVED_FROM, cookie=93855786, name=être ou ne pas être.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,501 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt, wd=4, mask=IN_MOVED_TO, cookie=93855786, name=être ou ne pas être.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,505 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,505 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,505 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'> on known pair: StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,506 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder, remote_ref=None]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,506 140006829958912 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,506 140006829958912 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[5](Folderish:True, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,507 140006829958912 TRACE    nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 2
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,508 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,510 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,511 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,511 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt'> on known pair: StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,512 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/tre ou ne pas tre.odt, remote_ref=None]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,515 140006597322496 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"creationDate":1449465724508,"creator":"nuxeoDriveTestUser_user_1","folder":true,"parentId":"defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724508,"canRename":true,"name":"P\xc3\xb4le applicatif","id":"defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331","userName":"nuxeoDriveTestUser_user_1"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,516 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileCreatedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,516 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [created] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,520 140006597322496 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,520 140006597322496 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:True, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,521 140006597322496 TRACE    nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 3
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,521 140006597322496 TRACE    nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,521 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,522 140006597322496 TRACE    nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331' on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/P\xf4le applicatif'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,522 140006829958912 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,522 140006829958912 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[7](Folderish:False, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,523 140006829958912 TRACE    nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,523 140006597322496 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Pôle applicatif, remote_name=None, version=0] with version=0
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,522 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Pôle applicatif, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Pôle applicatif>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,523 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,523 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Pôle applicatif, wd=3, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,524 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,524 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Pôle applicatif, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Pôle applicatif>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,525 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Pôle applicatif, wd=3, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,525 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,526 140006588929792 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006588929792) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,527 140006605715200 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-45dd0d69-c580-4ba8-83a1-bb561a0605b2/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digestAlgorithm":"MD5","downloadURL":"nxfile/default/4e7dab1f-1eb4-49b1-94e0-23497a94ab6b/blobholder:0/Accentu%C3%A9.odt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1449465724515,"creator":"nuxeoDriveTestUser_user_1","folder":false,"parentId":"defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724515,"canRename":true,"name":"Accentu\xc3\xa9.odt","id":"defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b","userName":"nuxeoDriveTestUser_user_1"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,527 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,528 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,528 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,528 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,529 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,529 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,530 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,530 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,530 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,531 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 5 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,531 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,537 140006605715200 TRACE    nxdrive.engine.processor Transfer speed 0 ko/s
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,539 140006588929792 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006588929792 for row 7
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,540 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,540 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,547 140006597322496 DEBUG    nxdrive.engine.dao.sqlite Queuing 0 children of 'StateRow[4](Local: u'/Nuxeo Drive Test Workspace/P\xf4le applicatif', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,548 140006597322496 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dbd6e478>> on doc pair StateRow[4](Local: u'/Nuxeo Drive Test Workspace/P\xf4le applicatif', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,548 140006597322496 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/pôle applicatif
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,549 140006588929792 DEBUG    nxdrive.engine.processor Executing processor on StateRow[7](Local: u'/Nuxeo Drive Test Workspace/No special character.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)(0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,549 140006588929792 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dbd6eb98>> on doc pair StateRow[7](Local: u'/Nuxeo Drive Test Workspace/No special character.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,550 140006588929792 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/No special character.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,549 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'> on known pair: StateRow[7](Local: u'/Nuxeo Drive Test Workspace/No special character.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,550 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher Don't update as in process StateRow[7](Local: u'/Nuxeo Drive Test Workspace/No special character.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,554 140006605715200 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,555 140006605715200 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:False, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,555 140006605715200 TRACE    nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,555 140006605715200 TRACE    nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,555 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,556 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,556 140006605715200 TRACE    nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b' on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,556 140006597322496 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006597322496
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,557 140006605715200 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Accentué.odt, remote_name=None, version=0] with version=0
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,557 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt, wd=2, mask=IN_ATTRIB, cookie=0, name=Accentué.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,557 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt, wd=2, mask=IN_ATTRIB, cookie=0, name=Accentué.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,558 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,558 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,559 140006597322496 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006597322496 for row 5
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,559 140006597322496 DEBUG    nxdrive.engine.processor Executing processor on StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: None, Local state: created, Remote state: unknown, State: locally_created)(1)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,560 140006597322496 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dbd6e478>> on doc pair StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,560 140006597322496 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Sub folder
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,560 140006572144384 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006572144384) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,561 140006572144384 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006572144384) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,562 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,568 140006605715200 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dc641b98>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,568 140006605715200 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/accentué.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,570 140006580537088 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006580537088 for row 3
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,571 140006605715200 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006605715200
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,571 140006605715200 DEBUG    nxdrive.engine.workers Thread LocalFileProcessor(140006605715200) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,571 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,572 140006580537088 DEBUG    nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b, Local state: synchronized, Remote state: synchronized, State: synchronized)(0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,572 140006580537088 TRACE    nxdrive.engine.processor Skip as pair is in non-processable state: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,575 140006580537088 TRACE    nxdrive.engine.dao.sqlite Released processor 140006580537088
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,576 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,576 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,580 140006597322496 TRACE    nxdrive.engine.processor Entered _synchronize_locally_created, parent_pair = StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,581 140006597322496 DEBUG    nxdrive.engine.processor Creating remote folder 'Sub folder' in folder 'Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,581 140006597322496 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'name': u'Sub folder', 'parentId': u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,581 140006597322496 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": "Sub folder", "parentId": "defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,584 140006588929792 TRACE    nxdrive.engine.processor Entered _synchronize_locally_created, parent_pair = StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,584 140006588929792 DEBUG    nxdrive.engine.processor Creating remote document 'No special character.odt' in folder 'Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,590 140006588929792 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-508a40ff-1467-4d88-9452-049c8aaf1464"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,590 140006588929792 TRACE    nxdrive.utils      Guessed mime type 'application/vnd.oasis.opendocument.text' for 'No special character.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,590 140006588929792 TRACE    nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 4096 bytes
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,590 140006588929792 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-508a40ff-1467-4d88-9452-049c8aaf1464/0 with headers {'Content-Length': 7, 'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 7, 'Cache-Control': 'no-cache', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': 'No%20special%20character.odt', 'X-Client-Version': '2.0-dev'} and cookies [] for file /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,594 140006588929792 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-508a40ff-1467-4d88-9452-049c8aaf1464/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"7","uploadType":"normal","batchId":"batchId-508a40ff-1467-4d88-9452-049c8aaf1464"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,594 140006588929792 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 /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,594 140006588929792 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,594 140006588929792 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-508a40ff-1467-4d88-9452-049c8aaf1464/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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#715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,602 140006597322496 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.CreateFolder' with cookies []: '{"canCreateChild":true,"creationDate":1449465724596,"creator":"nuxeoDriveTestUser_user_1","folder":true,"parentId":"defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724596,"canRename":true,"name":"Sub folder","id":"defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb","userName":"nuxeoDriveTestUser_user_1"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,605 140006597322496 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,605 140006597322496 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[5](Folderish:True, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,605 140006597322496 TRACE    nxdrive.engine.queue_manager Pushed to _local_folder_queue, now of size: 3
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,605 140006597322496 TRACE    nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,606 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,606 140006597322496 TRACE    nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb' on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,606 140006597322496 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Sub folder, remote_name=None, version=1] with version=1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,606 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Sub folder>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,607 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder, wd=4, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,607 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder, wd=2, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=Sub folder>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,608 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder, wd=4, mask=IN_ATTRIB|IN_ISDIR, cookie=0, name=>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,609 140006597322496 DEBUG    nxdrive.engine.dao.sqlite Queuing 1 children of 'StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: None, Local state: created, Remote state: unknown, State: locally_created)'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,609 140006597322496 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,610 140006597322496 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:0, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,610 140006597322496 TRACE    nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,610 140006597322496 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dbd6e478>> on doc pair StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,610 140006597322496 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/sub folder
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,610 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,610 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,611 140006597322496 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006597322496
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,611 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,611 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,612 140006605715200 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006605715200) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,612 140006605715200 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006605715200) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,612 140006597322496 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006597322496 for row 5
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,612 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,613 140006597322496 DEBUG    nxdrive.engine.processor Executing processor on StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb, Local state: synchronized, Remote state: synchronized, State: synchronized)(1)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,613 140006597322496 TRACE    nxdrive.engine.processor Skip as pair is in non-processable state: StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,613 140006597322496 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/sub folder
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,613 140006597322496 TRACE    nxdrive.engine.processor u'/nuxeo drive test workspace/sub folder'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,619 140006580537088 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006580537088 for row 6
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,623 140006597322496 TRACE    nxdrive.engine.dao.sqlite Released processor 140006597322496
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,624 140006597322496 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006597322496 for row 4
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,625 140006597322496 DEBUG    nxdrive.engine.processor Executing processor on StateRow[4](Local: u'/Nuxeo Drive Test Workspace/P\xf4le applicatif', Remote: defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331, Local state: synchronized, Remote state: synchronized, State: synchronized)(0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,625 140006597322496 TRACE    nxdrive.engine.processor Skip as pair is in non-processable state: StateRow[4](Local: u'/Nuxeo Drive Test Workspace/P\xf4le applicatif', Remote: defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,625 140006597322496 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/sub folder
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,625 140006597322496 TRACE    nxdrive.engine.processor u'/nuxeo drive test workspace/sub folder'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,630 140006597322496 TRACE    nxdrive.engine.dao.sqlite Released processor 140006597322496
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,631 140006588929792 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-508a40ff-1467-4d88-9452-049c8aaf1464/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digestAlgorithm":"MD5","downloadURL":"nxfile/default/b8e33edf-18e9-42b1-bcda-c682b91390de/blobholder:0/No%20special%20character.odt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1449465724619,"creator":"nuxeoDriveTestUser_user_1","folder":false,"parentId":"defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724619,"canRename":true,"name":"No special character.odt","id":"defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de","userName":"nuxeoDriveTestUser_user_1"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,631 140006597322496 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006597322496 for row 5
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,632 140006597322496 DEBUG    nxdrive.engine.processor Executing processor on StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb, Local state: synchronized, Remote state: synchronized, State: synchronized)(1)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,632 140006597322496 TRACE    nxdrive.engine.processor Skip as pair is in non-processable state: StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,632 140006597322496 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/sub folder
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,632 140006597322496 TRACE    nxdrive.engine.processor u'/nuxeo drive test workspace/sub folder'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,638 140006588929792 TRACE    nxdrive.engine.processor Transfer speed 1 ko/s
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,647 140006597322496 TRACE    nxdrive.engine.dao.sqlite Released processor 140006597322496
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,648 140006597322496 DEBUG    nxdrive.engine.workers Thread LocalFolderProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,650 140006588929792 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,650 140006588929792 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[7](Folderish:False, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,651 140006588929792 TRACE    nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,651 140006588929792 TRACE    nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,651 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,651 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,652 140006588929792 TRACE    nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de' on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,652 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,653 140006597322496 TRACE    nxdrive.engine.dao.sqlite Couldn't acquire processor 140006597322496 for row 7: either row does't exist or it is being processed
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,653 140006588929792 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/No special character.odt, remote_name=None, version=0] with version=0
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,653 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt, wd=2, mask=IN_ATTRIB, cookie=0, name=No special character.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,654 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt, wd=2, mask=IN_ATTRIB, cookie=0, name=No special character.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,654 140006580537088 DEBUG    nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)(1)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,655 140006597322496 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006597322496
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,656 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,657 140006580537088 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dbd2c180>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,657 140006580537088 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,659 140006588929792 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dbd6eb98>> on doc pair StateRow[7](Local: u'/Nuxeo Drive Test Workspace/No special character.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,659 140006588929792 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/no special character.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,660 140006588929792 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006588929792
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,660 140006588929792 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006588929792) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,663 140006580537088 TRACE    nxdrive.engine.processor Entered _synchronize_locally_created, parent_pair = StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,663 140006580537088 DEBUG    nxdrive.engine.processor Creating remote document 'être ou ne pas être.odt' in folder 'Sub folder'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,668 140006580537088 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload' with cookies []: '{"batchId":"batchId-484d3356-7fca-4fa3-8959-cf0b73ca6710"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,668 140006580537088 TRACE    nxdrive.utils      Guessed mime type 'application/vnd.oasis.opendocument.text' for 'être ou ne pas être.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,668 140006580537088 TRACE    nxdrive.client.base_automation_client Using file system block size for the streaming upload buffer: 4096 bytes
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,668 140006580537088 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-484d3356-7fca-4fa3-8959-cf0b73ca6710/0 with headers {'Content-Length': 7, 'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', 'X-File-Type': 'application/vnd.oasis.opendocument.text', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-File-Size': 7, 'Cache-Control': 'no-cache', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'Content-Type': 'application/octet-stream', 'X-Application-Name': 'Nuxeo Drive', 'X-File-Name': '%C3%AAtre%20ou%20ne%20pas%20%C3%AAtre.odt', 'X-Client-Version': '2.0-dev'} and cookies [] for file /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,673 140006580537088 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-484d3356-7fca-4fa3-8959-cf0b73ca6710/0' with cookies []: '{"uploaded":"true","fileIdx":"0","uploadedSize":"7","uploadType":"normal","batchId":"batchId-484d3356-7fca-4fa3-8959-cf0b73ca6710"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,673 140006580537088 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 /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,673 140006580537088 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'parentId': u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,673 140006580537088 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/api/v1/upload/batchId-484d3356-7fca-4fa3-8959-cf0b73ca6710/0/execute/NuxeoDrive.CreateFile with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', 'Accept': 'application/json+nxentity, */*', 'User-Agent': 'Nuxeo Drive/2.0-dev', 'X-User-Id': u'nuxeoDriveTestUser_user_1', 'X-Application-Name': 'Nuxeo Drive', 'Cache-Control': 'no-cache', 'Content-Type': 'application/json+nxrequest', 'Nuxeo-Transaction-Timeout': 300, 'X-Client-Version': '2.0-dev'}, cookies [] and JSON payload '{"params": {"parentId": "defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,706 140006580537088 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/api/v1/upload/batchId-484d3356-7fca-4fa3-8959-cf0b73ca6710/0/execute/NuxeoDrive.CreateFile' with cookies []: '{"digestAlgorithm":"MD5","downloadURL":"nxfile/default/a7922294-6bab-4a2d-a5b5-0d3ff266d385/blobholder:0/%C3%AAtre%20ou%20ne%20pas%20%C3%AAtre.odt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1449465724697,"creator":"nuxeoDriveTestUser_user_1","folder":false,"parentId":"defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724697,"canRename":true,"name":"\xc3\xaatre ou ne pas \xc3\xaatre.odt","id":"defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb/defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385","userName":"nuxeoDriveTestUser_user_1"}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,710 140006580537088 TRACE    nxdrive.engine.processor Transfer speed 0 ko/s
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,712 140006580537088 TRACE    nxdrive.engine.dao.sqlite Push to queue: locally_created: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,712 140006580537088 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:False, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,712 140006580537088 TRACE    nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,712 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,713 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,713 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,713 140006588929792 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006588929792) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,712 140006580537088 TRACE    nxdrive.engine.processor Put remote_ref in defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,715 140006580537088 TRACE    nxdrive.client.local_client Setting xattr ndrive with value u'defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385' on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,715 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,716 140006588929792 TRACE    nxdrive.engine.dao.sqlite Couldn't acquire processor 140006588929792 for row 6: either row does't exist or it is being processed
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,716 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt, wd=4, mask=IN_ATTRIB, cookie=0, name=être ou ne pas être.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,716 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,716 140006580537088 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt, remote_name=None, version=1] with version=1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,717 140006722955008 DEBUG    watchdog.observers.inotify_buffer in-event <InotifyEvent: src_path=/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt, wd=4, mask=IN_ATTRIB, cookie=0, name=être ou ne pas être.odt>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,717 140006588929792 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006588929792
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,718 140006588929792 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006588929792) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,720 140006580537088 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_locally_created of <nxdrive.engine.processor.Processor object at 0x7f55dbd2c180>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: None, Local state: created, Remote state: unknown, State: locally_created)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,720 140006580537088 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,720 140006580537088 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006580537088
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,720 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,928 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileMovedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt', dest_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,928 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,928 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileMovedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt', dest_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,928 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [moved] on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt to /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentué.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,929 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileMovedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt', dest_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'> on known pair: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,929 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Ignoring move from u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentue\u0301.odt' to normalized name: u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,929 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,930 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,930 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace'> on known pair: StateRow[2](Local: u'/Nuxeo Drive Test Workspace', Remote: defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:04,930 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 6 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace, remote_ref=defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,042 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileMovedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt', dest_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,042 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,042 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/P\xf4le applicatif'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,049 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileMovedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt', dest_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,049 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [moved] on /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt to /opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,050 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileMovedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt', dest_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'> on known pair: StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,050 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Ignoring move from u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/e\u0302tre ou ne pas \xeatre.odt' to normalized name: u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,050 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,050 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,051 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'> on known pair: StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,052 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 2 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder, remote_ref=defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,056 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/P\xf4le applicatif'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,056 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/P\xf4le applicatif'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,057 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/P\xf4le applicatif'> on known pair: StateRow[4](Local: u'/Nuxeo Drive Test Workspace/P\xf4le applicatif', Remote: defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,057 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 1 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Ple applicatif, remote_ref=defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,058 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,058 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,059 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,059 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,059 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'> on known pair: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,060 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Accentué.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,060 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,060 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,060 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Accentu\xe9.odt'> on known pair: StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,061 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Accentué.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,122 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,122 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,123 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,123 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <DirModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder'> on known pair: StateRow[5](Local: u'/Nuxeo Drive Test Workspace/Sub folder', Remote: defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,124 140006829958912 TRACE    nxdrive.engine.dao.sqlite Increasing version to 3 for pair FileInfo[/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder, remote_ref=defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb]
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,186 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,187 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,188 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,188 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/No special character.odt'> on known pair: StateRow[7](Local: u'/Nuxeo Drive Test Workspace/No special character.odt', Remote: defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,189 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/No special character.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,218 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,218 140006731347712 TRACE    nxdrive.engine.watcher.local_watcher Queueing watchdog: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,220 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,220 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,221 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'> on known pair: StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,222 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,222 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event: <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'>
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,222 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Handling watchdog event [modified] on u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,222 140006829958912 TRACE    nxdrive.engine.watcher.local_watcher watchdog event <FileModifiedEvent: src_path=u'/opt/jenkins/workspace/FT-nuxeo-drive-master-linux/tmp/tmpCy9c34-nxdrive-tests-user-1/Nuxeo Drive/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt'> on known pair: StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385, Local state: synchronized, Remote state: synchronized, State: synchronized)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:05,223 140006829958912 DEBUG    nxdrive.engine.watcher.local_watcher Dropping watchdog event [modified] as digest has not changed for /Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,219 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,219 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 13828, 'lastSyncActiveRootDefinitions': u'default:715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,219 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": 13828, "lastSyncActiveRootDefinitions": "default:715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,235 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":13851,"fileSystemChanges":[{"eventId":"documentCreated","eventDate":1449465724697,"repositoryId":"default","fileSystemItem":{"digestAlgorithm":"MD5","downloadURL":"nxfile/default/a7922294-6bab-4a2d-a5b5-0d3ff266d385/blobholder:0/%C3%AAtre%20ou%20ne%20pas%20%C3%AAtre.odt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1449465724697,"creator":"nuxeoDriveTestUser_user_1","folder":false,"parentId":"defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724697,"canRename":true,"name":"\xc3\xaatre ou ne pas \xc3\xaatre.odt","id":"defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb/defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385","userName":"nuxeoDriveTestUser_user_1"},"docUuid":"a7922294-6bab-4a2d-a5b5-0d3ff266d385","fileSystemItemId":"defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385","fileSystemItemName":"\xc3\xaatre ou ne pas \xc3\xaatre.odt"},{"eventId":"documentCreated","eventDate":1449465724619,"repositoryId":"default","fileSystemItem":{"digestAlgorithm":"MD5","downloadURL":"nxfile/default/b8e33edf-18e9-42b1-bcda-c682b91390de/blobholder:0/No%20special%20character.odt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1449465724619,"creator":"nuxeoDriveTestUser_user_1","folder":false,"parentId":"defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724619,"canRename":true,"name":"No special character.odt","id":"defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de","userName":"nuxeoDriveTestUser_user_1"},"docUuid":"b8e33edf-18e9-42b1-bcda-c682b91390de","fileSystemItemId":"defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de","fileSystemItemName":"No special character.odt"},{"eventId":"documentCreated","eventDate":1449465724596,"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"creationDate":1449465724596,"creator":"nuxeoDriveTestUser_user_1","folder":true,"parentId":"defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724596,"canRename":true,"name":"Sub folder","id":"defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb","userName":"nuxeoDriveTestUser_user_1"},"docUuid":"e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb","fileSystemItemId":"defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb","fileSystemItemName":"Sub folder"},{"eventId":"documentCreated","eventDate":1449465724515,"repositoryId":"default","fileSystemItem":{"digestAlgorithm":"MD5","downloadURL":"nxfile/default/4e7dab1f-1eb4-49b1-94e0-23497a94ab6b/blobholder:0/Accentu%C3%A9.odt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1449465724515,"creator":"nuxeoDriveTestUser_user_1","folder":false,"parentId":"defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724515,"canRename":true,"name":"Accentu\xc3\xa9.odt","id":"defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b","userName":"nuxeoDriveTestUser_user_1"},"docUuid":"4e7dab1f-1eb4-49b1-94e0-23497a94ab6b","fileSystemItemId":"defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b","fileSystemItemName":"Accentu\xc3\xa9.odt"},{"eventId":"documentCreated","eventDate":1449465724508,"repositoryId":"default","fileSystemItem":{"canCreateChild":true,"creationDate":1449465724508,"creator":"nuxeoDriveTestUser_user_1","folder":true,"parentId":"defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724508,"canRename":true,"name":"P\xc3\xb4le applicatif","id":"defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331","userName":"nuxeoDriveTestUser_user_1"},"docUuid":"15428dd7-11fd-4d66-870c-919100254331","fileSystemItemId":"defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331","fileSystemItemName":"P\xc3\xb4le applicatif"}],"activeSynchronizationRootDefinitions":"default:715d569b-89c4-43b3-b66b-781cd14ff53c","syncDate":1449465726000}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,236 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher 5 remote changes detected
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,236 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,236 140009472325440 DEBUG    nxdrive.tests.common_unit_test Remote changes slot for: 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,236 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting finished...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,237 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'canUpdate': True, u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'\xeatre ou ne pas \xeatre.odt', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'digestAlgorithm': u'MD5', u'lastModificationDate': 1449465724697, u'id': u'defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385', u'downloadURL': u'nxfile/default/a7922294-6bab-4a2d-a5b5-0d3ff266d385/blobholder:0/%C3%AAtre%20ou%20ne%20pas%20%C3%AAtre.odt', u'parentId': u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb/defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385', u'folder': False, u'creationDate': 1449465724697, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True, u'digest': u'f15c1cae7882448b3fb0404682e17e61'}, u'fileSystemItemId': u'defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385', u'fileSystemItemName': u'\xeatre ou ne pas \xeatre.odt', u'repositoryId': u'default', u'docUuid': u'a7922294-6bab-4a2d-a5b5-0d3ff266d385', u'eventDate': 1449465724697}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,237 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt' (force_recursion:0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,237 140006706169600 TRACE    nxdrive.engine.dao.sqlite Increasing version to 2 for pair RemoteFileInfo(name=u'\xeatre ou ne pas \xeatre.odt', uid=u'defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385', parent_uid=u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb/defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385', folderish=False, last_modification_time=datetime.datetime(2015, 12, 7, 5, 22, 4), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxfile/default/a7922294-6bab-4a2d-a5b5-0d3ff266d385/blobholder:0/%C3%AAtre%20ou%20ne%20pas%20%C3%AAtre.odt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,245 140006706169600 TRACE    nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,245 140006706169600 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:False, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,245 140006706169600 TRACE    nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,245 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,246 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,246 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,246 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,247 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,247 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,248 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,247 140006588929792 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006588929792) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,248 140006588929792 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006588929792) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,252 140006580537088 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006580537088 for row 6
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,253 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,253 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting finished...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,253 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'canUpdate': True, u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'No special character.odt', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'digestAlgorithm': u'MD5', u'lastModificationDate': 1449465724619, u'id': u'defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de', u'downloadURL': u'nxfile/default/b8e33edf-18e9-42b1-bcda-c682b91390de/blobholder:0/No%20special%20character.odt', u'parentId': u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de', u'folder': False, u'creationDate': 1449465724619, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True, u'digest': u'f15c1cae7882448b3fb0404682e17e61'}, u'fileSystemItemId': u'defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de', u'fileSystemItemName': u'No special character.odt', u'repositoryId': u'default', u'docUuid': u'b8e33edf-18e9-42b1-bcda-c682b91390de', u'eventDate': 1449465724619}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,253 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/No special character.odt' (force_recursion:0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,254 140006706169600 TRACE    nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'No special character.odt', uid=u'defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de', parent_uid=u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de', folderish=False, last_modification_time=datetime.datetime(2015, 12, 7, 5, 22, 4), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxfile/default/b8e33edf-18e9-42b1-bcda-c682b91390de/blobholder:0/No%20special%20character.odt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,254 140006580537088 DEBUG    nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385, Local state: synchronized, Remote state: modified, State: remotely_modified)(2)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,254 140006580537088 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f55dbd2cd60>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385, Local state: synchronized, Remote state: modified, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,255 140006580537088 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,258 140006706169600 TRACE    nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,258 140006706169600 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[7](Folderish:False, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,258 140006706169600 TRACE    nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,258 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,259 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,259 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,259 140006588929792 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006588929792) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,260 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,260 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,263 140006588929792 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006588929792 for row 7
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,265 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,265 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting finished...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,265 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'Sub folder', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'lastModificationDate': 1449465724596, u'id': u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', u'canCreateChild': True, u'parentId': u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', u'folder': True, u'creationDate': 1449465724596, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True}, u'fileSystemItemId': u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', u'fileSystemItemName': u'Sub folder', u'repositoryId': u'default', u'docUuid': u'e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', u'eventDate': 1449465724596}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,265 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Sub folder' (force_recursion:0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,266 140006706169600 TRACE    nxdrive.engine.dao.sqlite Increasing version to 4 for pair RemoteFileInfo(name=u'Sub folder', uid=u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', parent_uid=u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', folderish=True, last_modification_time=datetime.datetime(2015, 12, 7, 5, 22, 4), 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)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,266 140006706169600 TRACE    nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,266 140006706169600 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[5](Folderish:True, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,267 140006706169600 TRACE    nxdrive.engine.queue_manager Pushed to _remote_folder_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,267 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,267 140006588929792 DEBUG    nxdrive.engine.processor Executing processor on StateRow[7](Local: u'/Nuxeo Drive Test Workspace/No special character.odt', Remote: defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de, Local state: synchronized, Remote state: modified, State: remotely_modified)(1)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,267 140006588929792 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f55dbcd93e0>> on doc pair StateRow[7](Local: u'/Nuxeo Drive Test Workspace/No special character.odt', Remote: defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de, Local state: synchronized, Remote state: modified, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,268 140006588929792 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/No special character.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,272 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Remote scanning: /Nuxeo Drive Test Workspace/Sub folder
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,272 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,272 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,273 140006580537088 DEBUG    nxdrive.engine.processor No local impact of metadata update on document 'être ou ne pas être.odt'.
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,274 140006580537088 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt, remote_name=être ou ne pas être.odt, version=2] with version=2
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,279 140006580537088 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f55dbd2cd60>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385, Local state: synchronized, Remote state: modified, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,279 140006580537088 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,279 140006580537088 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006580537088
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,279 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,280 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,285 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[{"digestAlgorithm":"MD5","downloadURL":"nxfile/default/a7922294-6bab-4a2d-a5b5-0d3ff266d385/blobholder:0/%C3%AAtre%20ou%20ne%20pas%20%C3%AAtre.odt","canUpdate":true,"digest":"f15c1cae7882448b3fb0404682e17e61","creationDate":1449465724697,"creator":"nuxeoDriveTestUser_user_1","folder":false,"parentId":"defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb","canDelete":true,"lastContributor":"nuxeoDriveTestUser_user_1","lastModificationDate":1449465724697,"canRename":true,"name":"\xc3\xaatre ou ne pas \xc3\xaatre.odt","id":"defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385","path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb/defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385","userName":"nuxeoDriveTestUser_user_1"}]'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,285 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Scanning remote child: RemoteFileInfo(name=u'\xeatre ou ne pas \xeatre.odt', uid=u'defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385', parent_uid=u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb/defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385', folderish=False, last_modification_time=datetime.datetime(2015, 12, 7, 5, 22, 4), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxfile/default/a7922294-6bab-4a2d-a5b5-0d3ff266d385/blobholder:0/%C3%AAtre%20ou%20ne%20pas%20%C3%AAtre.odt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,285 140006706169600 TRACE    nxdrive.engine.dao.sqlite Increasing version to 3 for pair RemoteFileInfo(name=u'\xeatre ou ne pas \xeatre.odt', uid=u'defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385', parent_uid=u'defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#e36ba8b7-f4ae-44be-98ca-aa0f3e51c6eb/defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385', folderish=False, last_modification_time=datetime.datetime(2015, 12, 7, 5, 22, 4), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxfile/default/a7922294-6bab-4a2d-a5b5-0d3ff266d385/blobholder:0/%C3%AAtre%20ou%20ne%20pas%20%C3%AAtre.odt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,287 140006706169600 TRACE    nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,287 140006706169600 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[6](Folderish:False, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,287 140006706169600 TRACE    nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,287 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,288 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,288 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,288 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,289 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,289 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,289 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,297 140006580537088 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006580537088 for row 6
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,301 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,301 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting finished...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,301 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'canUpdate': True, u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'Accentu\xe9.odt', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'digestAlgorithm': u'MD5', u'lastModificationDate': 1449465724515, u'id': u'defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b', u'downloadURL': u'nxfile/default/4e7dab1f-1eb4-49b1-94e0-23497a94ab6b/blobholder:0/Accentu%C3%A9.odt', u'parentId': u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b', u'folder': False, u'creationDate': 1449465724515, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True, u'digest': u'f15c1cae7882448b3fb0404682e17e61'}, u'fileSystemItemId': u'defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b', u'fileSystemItemName': u'Accentu\xe9.odt', u'repositoryId': u'default', u'docUuid': u'4e7dab1f-1eb4-49b1-94e0-23497a94ab6b', u'eventDate': 1449465724515}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,302 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Accentué.odt' (force_recursion:0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,302 140006706169600 TRACE    nxdrive.engine.dao.sqlite Increasing version to 1 for pair RemoteFileInfo(name=u'Accentu\xe9.odt', uid=u'defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b', parent_uid=u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b', folderish=False, last_modification_time=datetime.datetime(2015, 12, 7, 5, 22, 4), last_contributor=u'nuxeoDriveTestUser_user_1', digest=u'f15c1cae7882448b3fb0404682e17e61', digest_algorithm=u'md5', download_url=u'nxfile/default/4e7dab1f-1eb4-49b1-94e0-23497a94ab6b/blobholder:0/Accentu%C3%A9.odt', can_rename=True, can_delete=True, can_update=True, can_create_child=False)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,303 140006706169600 TRACE    nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,303 140006706169600 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[3](Folderish:False, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,303 140006706169600 TRACE    nxdrive.engine.queue_manager Pushed to _remote_file_queue, now of size: 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,304 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,304 140009472325440 DEBUG    nxdrive.engine.queue_manager creating additional file processor
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,304 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) start
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,305 140006597322496 TRACE    nxdrive.engine.dao.sqlite Acquired processor 140006597322496 for row 3
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,314 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,314 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Interacting finished...
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,315 140006706169600 TRACE    nxdrive.engine.watcher.remote_watcher Processing event: {u'eventId': u'documentCreated', u'fileSystemItem': {u'userName': u'nuxeoDriveTestUser_user_1', u'name': u'P\xf4le applicatif', u'canDelete': True, u'creator': u'nuxeoDriveTestUser_user_1', u'lastModificationDate': 1449465724508, u'id': u'defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331', u'canCreateChild': True, u'parentId': u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', u'path': u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331', u'folder': True, u'creationDate': 1449465724508, u'lastContributor': u'nuxeoDriveTestUser_user_1', u'canRename': True}, u'fileSystemItemId': u'defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331', u'fileSystemItemName': u'P\xf4le applicatif', u'repositoryId': u'default', u'docUuid': u'15428dd7-11fd-4d66-870c-919100254331', u'eventDate': 1449465724508}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,315 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Refreshing remote state info for doc_pair '/Nuxeo Drive Test Workspace/Pôle applicatif' (force_recursion:0)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,315 140006706169600 TRACE    nxdrive.engine.dao.sqlite Increasing version to 2 for pair RemoteFileInfo(name=u'P\xf4le applicatif', uid=u'defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331', parent_uid=u'defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c', path=u'/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#715d569b-89c4-43b3-b66b-781cd14ff53c/defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331', folderish=True, last_modification_time=datetime.datetime(2015, 12, 7, 5, 22, 4), 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)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,316 140006706169600 TRACE    nxdrive.engine.dao.sqlite Push to queue: remotely_modified: None
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,316 140006706169600 TRACE    nxdrive.engine.queue_manager Pushing QueueItem[4](Folderish:True, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,316 140006706169600 TRACE    nxdrive.engine.queue_manager Pushed to _remote_folder_queue, now of size: 2
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,316 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,317 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Remote scanning: /Nuxeo Drive Test Workspace/Pôle applicatif
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,317 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'id': u'defaultFileSystemItemFactory#default#15428dd7-11fd-4d66-870c-919100254331'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,317 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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#15428dd7-11fd-4d66-870c-919100254331"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,322 140006588929792 DEBUG    nxdrive.engine.processor No local impact of metadata update on document 'No special character.odt'.
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,322 140006588929792 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/No special character.odt, remote_name=No special character.odt, version=1] with version=1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,323 140006588929792 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f55dbcd93e0>> on doc pair StateRow[7](Local: u'/Nuxeo Drive Test Workspace/No special character.odt', Remote: defaultFileSystemItemFactory#default#b8e33edf-18e9-42b1-bcda-c682b91390de, Local state: synchronized, Remote state: modified, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,324 140006588929792 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/no special character.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,324 140006588929792 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006588929792
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,324 140006588929792 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006588929792) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,324 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,325 140006597322496 DEBUG    nxdrive.engine.processor Executing processor on StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b, Local state: synchronized, Remote state: modified, State: remotely_modified)(1)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,325 140006597322496 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f55dbcd9e90>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b, Local state: synchronized, Remote state: modified, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,325 140006597322496 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Accentué.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,326 140006597322496 DEBUG    nxdrive.engine.processor No local impact of metadata update on document 'Accentué.odt'.
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,326 140006597322496 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Accentué.odt, remote_name=Accentué.odt, version=1] with version=1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,327 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChildren' with cookies []: '[]'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,329 140006597322496 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f55dbcd9e90>> on doc pair StateRow[3](Local: u'/Nuxeo Drive Test Workspace/Accentu\xe9.odt', Remote: defaultFileSystemItemFactory#default#4e7dab1f-1eb4-49b1-94e0-23497a94ab6b, Local state: synchronized, Remote state: modified, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,329 140006597322496 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/accentué.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,329 140006597322496 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006597322496
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,330 140006597322496 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006597322496) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,330 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,340 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,340 140009472325440 DEBUG    nxdrive.engine.engine Checking sync completed: queue manager is active, overall size = 2, empty polls count = 0
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,351 140006580537088 DEBUG    nxdrive.engine.processor Executing processor on StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385, Local state: synchronized, Remote state: modified, State: remotely_modified)(3)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,351 140006580537088 TRACE    nxdrive.engine.processor Calling <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f55dbcd9938>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385, Local state: synchronized, Remote state: modified, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,352 140006580537088 TRACE    nxdrive.engine.processor Soft locking: /Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,352 140006580537088 DEBUG    nxdrive.engine.processor No local impact of metadata update on document 'être ou ne pas être.odt'.
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,353 140006580537088 TRACE    nxdrive.engine.dao.sqlite Try to synchronize state for [local_path=/Nuxeo Drive Test Workspace/Sub folder/être ou ne pas être.odt, remote_name=être ou ne pas être.odt, version=3] with version=3
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,355 140006580537088 TRACE    nxdrive.engine.processor Finish <bound method Processor._synchronize_remotely_modified of <nxdrive.engine.processor.Processor object at 0x7f55dbcd9938>> on doc pair StateRow[6](Local: u'/Nuxeo Drive Test Workspace/Sub folder/\xeatre ou ne pas \xeatre.odt', Remote: defaultFileSystemItemFactory#default#a7922294-6bab-4a2d-a5b5-0d3ff266d385, Local state: synchronized, Remote state: modified, State: remotely_modified)
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,355 140006580537088 TRACE    nxdrive.engine.processor Soft unlocking: /nuxeo drive test workspace/sub folder/être ou ne pas être.odt
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,355 140006580537088 TRACE    nxdrive.engine.dao.sqlite No processor to release with id 140006580537088
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,355 140006580537088 DEBUG    nxdrive.engine.workers Thread GenericProcessor(140006580537088) end
06:22:24 [INFO]      [exec] 2015-12-07 05:22:06,356 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:09,381 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
06:22:24 [INFO]      [exec] 2015-12-07 05:22:09,382 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 13851, 'lastSyncActiveRootDefinitions': u'default:715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:09,382 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": 13851, "lastSyncActiveRootDefinitions": "default:715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:09,389 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":13857,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:715d569b-89c4-43b3-b66b-781cd14ff53c","syncDate":1449465729000}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:09,390 140009472325440 TRACE    nxdrive.tests.common_unit_test No remote changes slot for: 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:22:09,444 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:09,444 140009472325440 DEBUG    nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 2, empty polls count = 1
06:22:24 [INFO]      [exec] 2015-12-07 05:22:12,492 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
06:22:24 [INFO]      [exec] 2015-12-07 05:22:12,492 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 13857, 'lastSyncActiveRootDefinitions': u'default:715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:12,492 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": 13857, "lastSyncActiveRootDefinitions": "default:715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:12,498 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":13859,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:715d569b-89c4-43b3-b66b-781cd14ff53c","syncDate":1449465732000}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:12,498 140009472325440 TRACE    nxdrive.tests.common_unit_test No remote changes slot for: 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:22:12,556 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:12,556 140009472325440 DEBUG    nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 2, empty polls count = 2
06:22:24 [INFO]      [exec] 2015-12-07 05:22:15,592 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
06:22:24 [INFO]      [exec] 2015-12-07 05:22:15,592 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 13859, 'lastSyncActiveRootDefinitions': u'default:715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:15,593 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": 13859, "lastSyncActiveRootDefinitions": "default:715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:15,607 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":13861,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:715d569b-89c4-43b3-b66b-781cd14ff53c","syncDate":1449465735000}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:15,608 140009472325440 TRACE    nxdrive.tests.common_unit_test No remote changes slot for: 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:22:15,646 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:15,646 140009472325440 DEBUG    nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 2, empty polls count = 3
06:22:24 [INFO]      [exec] 2015-12-07 05:22:18,688 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
06:22:24 [INFO]      [exec] 2015-12-07 05:22:18,689 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 13861, 'lastSyncActiveRootDefinitions': u'default:715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:18,689 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": 13861, "lastSyncActiveRootDefinitions": "default:715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:18,694 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":13863,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:715d569b-89c4-43b3-b66b-781cd14ff53c","syncDate":1449465738000}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:18,694 140009472325440 TRACE    nxdrive.tests.common_unit_test No remote changes slot for: 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:22:18,764 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:18,764 140009472325440 DEBUG    nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 2, empty polls count = 4
06:22:24 [INFO]      [exec] 2015-12-07 05:22:21,811 140006706169600 DEBUG    nxdrive.engine.watcher.remote_watcher Handle remote changes, first_pass=False
06:22:24 [INFO]      [exec] 2015-12-07 05:22:21,811 140006706169600 TRACE    nxdrive.client.base_automation_client Dumping JSON structure: {'params': {'lowerBound': 13863, 'lastSyncActiveRootDefinitions': u'default:715d569b-89c4-43b3-b66b-781cd14ff53c'}}
06:22:24 [INFO]      [exec] 2015-12-07 05:22:21,812 140006706169600 TRACE    nxdrive.client.base_automation_client Calling http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary with headers {'X-Authentication-Token': '7a72b764-42cd-4a41-b38b-963da5b3bb9a', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-Device-Id': '6f8688609ca211e5a99c0242ac110003', '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": 13863, "lastSyncActiveRootDefinitions": "default:715d569b-89c4-43b3-b66b-781cd14ff53c"}}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:21,817 140006706169600 TRACE    nxdrive.client.base_automation_client Response for 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetChangeSummary' with cookies []: '{"hasTooManyChanges":false,"upperBound":13865,"fileSystemChanges":[],"activeSynchronizationRootDefinitions":"default:715d569b-89c4-43b3-b66b-781cd14ff53c","syncDate":1449465741000}'
06:22:24 [INFO]      [exec] 2015-12-07 05:22:21,818 140009472325440 TRACE    nxdrive.tests.common_unit_test No remote changes slot for: 6f9184ea9ca211e5a99c0242ac110003
06:22:24 [INFO]      [exec] 2015-12-07 05:22:22,215 140009472325440 TRACE    nxdrive.engine.queue_manager Launching processors
06:22:24 [INFO]      [exec] 2015-12-07 05:22:22,215 140009472325440 DEBUG    nxdrive.engine.engine Checking sync completed: queue manager is inactive, overall size = 2, empty polls count = 5
06:22:24 [INFO]      [exec] 2015-12-07 05:22:23,898 140009195947776 WARNING  nxdrive.tests.common_unit_test Wait for sync timeout has expired
06:22:24 [INFO]      [exec] --------------------- >> end captured logging << ---------------------

Attachments

Issue Links

is required by

NXDRIVE-507 Eradicate random bugs

Resolved

Activity

People

Assignee:

Antoine Taillefer

Reporter:

Antoine Taillefer

Participants:

Antoine Taillefer, Jenkins

Votes:

0 Vote for this issue

Watchers:

2 Start watching this issue

Dates

Created:

2015-12-07 11:48

Updated:

2016-01-19 17:01

Resolved:

2016-01-19 17:01