-
Type:
Bug
-
Status: Resolved
-
Priority:
Major
-
Resolution: Fixed
-
Affects Version/s: 4.0.0
-
Fix Version/s: 4.1.4
-
Component/s: Synchronizer
-
Environment:macOS
-
Tags:
-
Sprint:nxDrive 11.1.10
-
Story Points:2
When the NotFound error is raised during the processing of a file that has a valid uid, it seems that the code to synchronize locally created file doesn't discard the entry from the processing queue. Instead, it adds it back in. We end up with the processor looping over the same NotFound file over and over again.
This happened when editing a Bar.md file with Xcode, which briefly created Bar~.md during the save process. The Bar~.md apparently has the same xattrs, and it causes the loop.
Relevant logs (this is the exact part that loops over and over):
2018-10-23 17:05:27 41186 123145568432128 DEBUG nxdrive.engine.processor Executing processor on <StateRow[7] local_path='/test-ws/Foo/Bar~.md', remote_ref='defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b', local_state='created', remote_state='unknown', pair_state='locally_created', filter_path=None>(1)
2018-10-23 17:05:27 41186 123145568432128 DEBUG nuxeo.client Calling 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem' with headers={'Content-Type': 'application/json+nxrequest', 'X-NXproperties': '*', 'X-NXDocumentProperties': '*', 'X-NXRepository': 'default', 'X-Application-Name': 'Nuxeo Drive', 'X-Client-Version': '4.0.0', 'User-Agent': 'Nuxeo Drive/4.0.0', 'Accept': 'application/json+nxentity, */*', 'X-User-Id': 'Administrator', 'X-Device-Id': '2be8f93ad6d311e8a3d688e9fe5ab440', 'Cache-Control': 'no-cache'}, params='{"params": {"id": "defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b"}}' and cookies=<RequestsCookieJar[Cookie(version=0, name='X-Authentication-Token', value='60dbebac-462b-4c6a-898a-0a3816f30650', port=None, port_specified=False, domain='localhost.local', domain_specified=False, domain_initial_dot=False, path='/nuxeo', path_specified=True, secure=False, expires=None, discard=True, comment=None, comment_url=None, rest={}, rfc2109=False)]>
2018-10-23 17:05:27 41186 123145568432128 DEBUG urllib3.connectionpool http://localhost:8080 "POST /nuxeo/site/automation/NuxeoDrive.GetFileSystemItem HTTP/1.1" 200 875
2018-10-23 17:05:27 41186 123145568432128 DEBUG nuxeo.client Response from 'http://localhost:8080/nuxeo/site/automation/NuxeoDrive.GetFileSystemItem': '{"id":"defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b","parentId":"defaultFileSystemItemFactory#default#bbfae0f0-2ab5-4c0e-b3d2-ec00e05a3e04","name":"Bar.md","folder":false,"creator":"Administrator","lastContributor":"Administrator","creationDate":1539708386214,"lastModificationDate":1539708391278,"canRename":true,"canDelete":true,"lockInfo":null,"path":"/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#38273831-f124-4e90-a13c-8616c11b6ee5/defaultFileSystemItemFactory#default#bbfae0f0-2ab5-4c0e-b3d2-ec00e05a3e04/defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b","userName":"Administrator","downloadURL":"nxfile/default/d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b/blobholder:0/Bar.md","digestAlgorithm":"MD5","digest":"41885fd697275824077a386d038791ab","canUpdate":true}' with cookies <RequestsCookieJar[Cookie(version=0, name='X-Authentication-Token', value='60dbebac-462b-4c6a-898a-0a3816f30650', port=None, port_specified=False, domain='localhost.local', domain_specified=False, domain_initial_dot=False, path='/nuxeo', path_specified=True, secure=False, expires=None, discard=True, comment=None, comment_url=None, rest={}, rfc2109=False)]>
2018-10-23 17:05:27 41186 123145568432128 TRACE nxdrive.engine.dao.sqlite Updating remote state for row=<StateRow[7] local_path='/test-ws/Foo/Bar~.md', remote_ref='defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b', local_state='created', remote_state='unknown', pair_state='locally_created', filter_path=None> with info=<RemoteFileInfo can_create_child=False, can_delete=True, can_rename=True, can_scroll_descendants=False, can_update=True, creation_time=datetime.datetime(2018, 10, 16, 18, 46, 26), digest='41885fd697275824077a386d038791ab', digest_algorithm='md5', download_url='nxfile/default/d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b/blobholder:0/Bar.md', folderish=False, last_contributor='Administrator', last_modification_time=datetime.datetime(2018, 10, 16, 18, 46, 31), lock_created=None, lock_owner=None, name='Bar.md', parent_uid='defaultFileSystemItemFactory#default#bbfae0f0-2ab5-4c0e-b3d2-ec00e05a3e04', path='/org.nuxeo.drive.service.impl.DefaultTopLevelFolderItemFactory#/defaultSyncRootFolderItemFactory#default#38273831-f124-4e90-a13c-8616c11b6ee5/defaultFileSystemItemFactory#default#bbfae0f0-2ab5-4c0e-b3d2-ec00e05a3e04/defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b', uid='defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b'> (force=False)
2018-10-23 17:05:27 41186 123145568432128 TRACE nxdrive.engine.processor Calling _synchronize_locally_created() on doc pair <StateRow[7] local_path='/test-ws/Foo/Bar~.md', remote_ref='defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b', local_state='created', remote_state='unknown', pair_state='locally_created', filter_path=None>
2018-10-23 17:05:27 41186 123145568432128 TRACE nxdrive.engine.processor Soft locking '/test-ws/Foo/Bar~.md'
2018-10-23 17:05:27 41186 123145568432128 TRACE nxdrive.client.local_client Getting xattr 'ndrive' from '/Users/lea/Nuxeo Drive/test-ws/Foo/Bar~.md': None
2018-10-23 17:05:27 41186 123145568432128 TRACE nxdrive.engine.processor Entered _synchronize_locally_created, parent_pair = <StateRow[3] local_path='/test-ws/Foo', remote_ref='defaultFileSystemItemFactory#default#bbfae0f0-2ab5-4c0e-b3d2-ec00e05a3e04', local_state='synchronized', remote_state='synchronized', pair_state='synchronized', filter_path=None>
2018-10-23 17:05:27 41186 123145568432128 DEBUG nxdrive.engine.processor Creating remote document 'Bar~.md' in folder 'Foo'
2018-10-23 17:05:27 41186 123145568432128 ERROR nxdrive.engine.processor NotFound on <StateRow[7] local_path='/test-ws/Foo/Bar~.md', remote_ref='defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b', local_state='created', remote_state='unknown', pair_state='locally_created', filter_path=None>, wait 1s and requeue
2018-10-23 17:05:28 41186 123145568432128 TRACE nxdrive.engine.queue_manager Pushing <StateRow[7] local_path='/test-ws/Foo/Bar~.md', remote_ref='defaultFileSystemItemFactory#default#d9dc7ad4-3b3b-4884-a0e9-e1bd5fe7f30b', local_state='created', remote_state='unknown', pair_state='locally_created', filter_path=None>
2018-10-23 17:05:28 41186 123145568432128 TRACE nxdrive.engine.queue_manager Pushed to _local_file_queue, now of size: 1
2018-10-23 17:05:28 41186 123145568432128 TRACE nxdrive.engine.processor Soft unlocking '/test-ws/foo/bar~.md'
