search

SyncServerII / Neebla

Private and Self-Owned Social Media
MIT License
1 stars 2 forks source link

Rod has *lots* of pending uploads #25

Closed crspybits closed 3 years ago

crspybits commented 3 years ago

Rod has 185 pending uploads. How did that happen? I see this in the logs he's sent.

crspybits commented 3 years ago

Just got a fresh set of logs from Rod, this time with a status field from each UploadFileTracker. The UploadObjectTracker's are each in one of two states:

  1. All files for the UploadObjectTracker are in an uploading state (i.e., none of the uploads are completed).

  2. All files for the UploadObjectTracker are in an notStarted state.

I think I don't have a means of restarting uploads when somehow they are all in an uploading state but somehow the upload has failed. E.g., my UploadFileTrackers don't have some means of timing out.

I also think that I'm limiting the number of UploadObjectTrackers that can have files in an uploading state.

I need to look into the code and confirm both of these.

crspybits commented 3 years ago

Indeed, currently only five UploadObjectTracker's can be pending, in uploading state. See maxConcurrentFileGroupUploads in iOSBasics-- https://github.com/SyncServerII/iOSBasics.git

And that is how many UploadObjectTracker's have UploadFileTracker's in an uploading state in Rod's logs.

crspybits commented 3 years ago

On the first point, I'm looking at triggerUploads() in iOSBasics. There are two parts to that:

    func triggerUploads() throws {
        // Retry any upload objects that are still .uploading, but that have files that are not yet started.
        try triggerRetryFileUploads()

        // Trigger other upload objects that are .notStarted -- these will either be completely new uploads or uploads that were already tried before.
        try triggerQueuedUploads()
    }

triggerRetryFileUploads(): Retry uploads if at least one of the component uploads is in a .notStarted state. This will not apply because all of the files in each object are in an uploading state.

triggerQueuedUploads: Trigger new uploads, if the limit hasn't been reached. In Rod's case, the limit has been reached. So this will not apply.

crspybits commented 3 years ago

What happens if the same upload is retried, and it already happened? I.e., our record on the client has a status of uploading but it actually succeeded as a server request but we just didn't get the result of the request. What kind of response will we see on the retry? Need to try this as a test case.

crspybits commented 3 years ago

Upload retry cases:

1) If an upload is retried and it is a duplicate of a file in the current upload batch, you get a UploadFileResponse with a UploadsFinished value of duplicateFileUpload. This is not a failure, but I need to make sure iOSBasics is treating it as a success. The context is: That the upload batch has not yet completed. I believe this will not be useful in the case of batch size of one where the upload completed but the client just didn't get the response. Or if the batch size > 1 but all were completed, and the client just didn't get (say) the last response.

2) If a vN upload is retried, and its batch was entirely completed before hand, this is not a failure. The upload will just be repeated. vN uploads have change resolvers, and these change resolvers can deal with repeats. Some test code would still be good to ensure this behavior is operating as expected.

3) Similarly, what if a v0 upload is retried and its batch was entirely completed beforehand?

crspybits commented 3 years ago

Test to try-- to generate a concrete hypothesis as to why Rod got into this state.

1) Put device (e.g., iPhone) into offline mode. i.e., airplane mode.

2) Enqueue an upload of an object or comment.

3) Wait for a few hours-- for the access token to expire.

4) Restart the server to ensure that its current cache of access tokens/users for authorization is flushed.

5) Bring client device back online and do a sync from the Albums screen.

Expect: That the uploads will not complete. BUT: Will they fail and get retried? Will they only be in an .uploading state?

crspybits commented 3 years ago

While this is anecdotal and just evidence of a single case, I'd like to see if any of the requests in:

All files for the UploadObjectTracker are in an uploading state (i.e., none of the uploads are completed). (see this link above) made any progress on the server (e.g., if the client just didn't get a response).

This is by way of seeing how much effort really ought to be put on different kinds of error handling and recovery in iOSBasics.

2021-08-02 22:37:11.861 [Notice] [main] [SettingsScreenModel.swift:109] addAttachments(vc:) > Pending Uploads: UploadObjectTracker: fileGroupUUID: AA5AFBA2-C366-4F83-B881-FFEF6C8DCEA7; v0Upload: Optional(true); batchUUID: A4649560-A20E-4F49-9ABB-CEE3947C04CD:
    UploadFileTracker: fileUUID: 1B680C09-3B8E-486F-83FC-67993532DF17; fileVersion: nil; status: uploading; uploadIndex: 1; uploadCount: 3
    UploadFileTracker: fileUUID: 75C95CC9-BF03-4B1D-AD2D-C5B1BE30AD11; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3
    UploadFileTracker: fileUUID: 218039D4-6668-414D-949C-831AB81F3DC6; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 3

Each of these three files appear in the FileIndex on the server, as version 0. It appears this is the case of the successful upload report just not making it to the client. There is no record of these files in the Upload table.

UploadObjectTracker: fileGroupUUID: 5419CF0E-696F-4636-97EB-D758D3088FC6; v0Upload: Optional(true); batchUUID: 01D6D804-4C60-41FB-A8D7-5E01E6ACDE47:
    UploadFileTracker: fileUUID: 8002F0B6-5E66-4332-B83E-28075768B177; fileVersion: nil; status: uploading; uploadIndex: 1; uploadCount: 3
    UploadFileTracker: fileUUID: C0F990AD-8E46-46AE-A97B-3D3270F0EF78; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3
    UploadFileTracker: fileUUID: 85F13EAF-035C-4E94-B571-F65EC9394A71; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 3

This is a similar situation. Each of these files appears in the FileIndex. But the comment file is now at version 1-- someone else apparently having added a comment. There is no record of these files in the Upload table.

UploadObjectTracker: fileGroupUUID: BB7BA013-4E00-4A33-8028-9A0F20189880; v0Upload: Optional(false); batchUUID: 3A788599-CF53-4328-912C-700491A37FF9:
    UploadFileTracker: fileUUID: 130E7E3F-AFF9-4548-A52F-FDAB3CD1E296; fileVersion: nil; status: uploading; uploadIndex: 1; uploadCount: 1

This is clearly not a v0 upload. As expected, there are files for this file group in the FileIndex table. There is no record of these files in the Upload table. There are rows for this file group in the DeferredUpload table. And a record for this batchUUID. It is completed.

UploadObjectTracker: fileGroupUUID: 3C66CDD4-DCBF-478B-BDA2-94BAC12F0571; v0Upload: Optional(true); batchUUID: 04353B49-2BFC-43AE-A9BA-E87AEB06D22B:
    UploadFileTracker: fileUUID: 7A57C89F-73E4-4E97-9B2B-DA6CAB954215; fileVersion: nil; status: uploading; uploadIndex: 1; uploadCount: 4
    UploadFileTracker: fileUUID: FAE1DD16-6354-4814-BC6A-0AF8DFD52340; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 4
    UploadFileTracker: fileUUID: 5E0531A2-6E86-435E-859B-D4A13F3C7F54; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 4
    UploadFileTracker: fileUUID: B22449D3-BCAB-4E93-8B4A-74DCFC2E6C34; fileVersion: nil; status: uploading; uploadIndex: 4; uploadCount: 4

Each of these files appears in the FileIndex. Some files have version > 0. There is no record of these files in the Upload table.

UploadObjectTracker: fileGroupUUID: 731B8A15-44D4-4CB7-B6C8-ACFBBE17FD6F; v0Upload: Optional(false); batchUUID: 52B3140A-BAE9-4051-9D02-42C93213CA2E:
    UploadFileTracker: fileUUID: DFA1A574-7D20-40B1-8652-42B0E808FF5C; fileVersion: nil; status: uploading; uploadIndex: 1; uploadCount: 1

This is clearly not a v0 upload. As expected, there are files for this file group in the FileIndex table. There is no record of these files in the Upload table. There is a row for this file group in the DeferredUpload table for this batchUUID. It is completed.

crspybits commented 3 years ago

Some of Rod's pending uploads have missing files:

1) UploadObjectTracker: fileGroupUUID: AA5AFBA2-C366-4F83-B881-FFEF6C8DCEA7; v0Upload: Optional(true); batchUUID: A4649560-A20E-4F49-9ABB-CEE3947C04CD: UploadFileTracker: fileUUID: 1B680C09-3B8E-486F-83FC-67993532DF17; fileVersion: nil; status: uploaded; uploadIndex: 1; uploadCount: 3; expiry: Optional(2021-08-11 00:17:21 +0000); canReadFile: Optional(true) UploadFileTracker: fileUUID: 75C95CC9-BF03-4B1D-AD2D-C5B1BE30AD11; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false) UploadFileTracker: fileUUID: 218039D4-6668-414D-949C-831AB81F3DC6; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true)

2) UploadObjectTracker: fileGroupUUID: 5419CF0E-696F-4636-97EB-D758D3088FC6; v0Upload: Optional(true); batchUUID: 01D6D804-4C60-41FB-A8D7-5E01E6ACDE47: UploadFileTracker: fileUUID: 8002F0B6-5E66-4332-B83E-28075768B177; fileVersion: nil; status: uploading; uploadIndex: 1; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true) UploadFileTracker: fileUUID: C0F990AD-8E46-46AE-A97B-3D3270F0EF78; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false) UploadFileTracker: fileUUID: 85F13EAF-035C-4E94-B571-F65EC9394A71; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true)

3) UploadObjectTracker: fileGroupUUID: 3C66CDD4-DCBF-478B-BDA2-94BAC12F0571; v0Upload: Optional(true); batchUUID: 04353B49-2BFC-43AE-A9BA-E87AEB06D22B: UploadFileTracker: fileUUID: 7A57C89F-73E4-4E97-9B2B-DA6CAB954215; fileVersion: nil; status: uploading; uploadIndex: 1; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true) UploadFileTracker: fileUUID: FAE1DD16-6354-4814-BC6A-0AF8DFD52340; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true) UploadFileTracker: fileUUID: 5E0531A2-6E86-435E-859B-D4A13F3C7F54; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false) UploadFileTracker: fileUUID: B22449D3-BCAB-4E93-8B4A-74DCFC2E6C34; fileVersion: nil; status: uploading; uploadIndex: 4; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false)

crspybits commented 3 years ago

Specific UploadFileTracker's:

UploadFileTracker: fileUUID: 75C95CC9-BF03-4B1D-AD2D-C5B1BE30AD11; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false)

UploadFileTracker: fileUUID: C0F990AD-8E46-46AE-A97B-3D3270F0EF78; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false)

UploadFileTracker: fileUUID: 5E0531A2-6E86-435E-859B-D4A13F3C7F54; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false)

UploadFileTracker: fileUUID: B22449D3-BCAB-4E93-8B4A-74DCFC2E6C34; fileVersion: nil; status: uploading; uploadIndex: 4; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false)

Each of these are from v0 uploads.

crspybits commented 3 years ago

fileUUID: 75C95CC9-BF03-4B1D-AD2D-C5B1BE30AD11 is in the FileIndex. It is an image.

fileUUID: C0F990AD-8E46-46AE-A97B-3D3270F0EF78 is in the FileIndex. It is an image.

fileUUID: 5E0531A2-6E86-435E-859B-D4A13F3C7F54 is in the FileIndex. It is an url.

fileUUID: B22449D3-BCAB-4E93-8B4A-74DCFC2E6C34 is in the FileIndex. It is an image.

crspybits commented 3 years ago

File group AA5AFBA2-C366-4F83-B881-FFEF6C8DCEA7: Not marked as deleted in FileGroup table on server.

File group 5419CF0E-696F-4636-97EB-D758D3088FC6: Not marked as deleted in FileGroup table on server.

File group 3C66CDD4-DCBF-478B-BDA2-94BAC12F0571: Not marked as deleted in FileGroup table on server.

crspybits commented 3 years ago

Both images and urls are marked as immutable when uploaded. i.e., a copy is not made when uploaded, the actual user file is uploaded.

crspybits commented 3 years ago

File group AA5AFBA2-C366-4F83-B881-FFEF6C8DCEA7: sharing group: 60A52DB4-39A8-486A-976C-A1DE0C922919; sharing group not deleted; name: "🎲♦️ ♠️ ❤️♣️🎲 random"

File group 5419CF0E-696F-4636-97EB-D758D3088FC6: sharing group: 15BB1FAE-D5E5-4694-AE36-04D003802E18; sharing group not deleted; name: "🍗 chicken is the question "

File group 3C66CDD4-DCBF-478B-BDA2-94BAC12F0571: sharing group: 60A52DB4-39A8-486A-976C-A1DE0C922919; sharing group not deleted; name: "🎲♦️ ♠️ ❤️♣️🎲 random"

crspybits commented 3 years ago

Most recent debugging info:

File group AA5AFBA2-C366-4F83-B881-FFEF6C8DCEA7: UploadObjectTracker: fileGroupUUID: AA5AFBA2-C366-4F83-B881-FFEF6C8DCEA7; v0Upload: Optional(true); batchUUID: A4649560-A20E-4F49-9ABB-CEE3947C04CD; deletedLocally: Optional(false); deletedOnServer: Optional(false) UploadFileTracker: fileUUID: 1B680C09-3B8E-486F-83FC-67993532DF17; fileVersion: nil; status: uploaded; uploadIndex: 1; uploadCount: 3; expiry: Optional(2021-08-11 00:17:21 +0000); canReadFile: Optional(true); mimeType: text; uploadCopy: true; deletedLocally: nil; deletedOnServer: nil UploadFileTracker: fileUUID: 75C95CC9-BF03-4B1D-AD2D-C5B1BE30AD11; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false); mimeType: jpeg; uploadCopy: false; deletedLocally: nil; deletedOnServer: nil UploadFileTracker: fileUUID: 218039D4-6668-414D-949C-831AB81F3DC6; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true); mimeType: text; uploadCopy: true; deletedLocally: nil; deletedOnServer: nil

File group 5419CF0E-696F-4636-97EB-D758D3088FC6: UploadObjectTracker: fileGroupUUID: 5419CF0E-696F-4636-97EB-D758D3088FC6; v0Upload: Optional(true); batchUUID: 01D6D804-4C60-41FB-A8D7-5E01E6ACDE47; deletedLocally: Optional(false); deletedOnServer: Optional(false) UploadFileTracker: fileUUID: 8002F0B6-5E66-4332-B83E-28075768B177; fileVersion: nil; status: uploading; uploadIndex: 1; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true); mimeType: text; uploadCopy: true; deletedLocally: nil; deletedOnServer: nil UploadFileTracker: fileUUID: C0F990AD-8E46-46AE-A97B-3D3270F0EF78; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false); mimeType: jpeg; uploadCopy: false; deletedLocally: nil; deletedOnServer: nil UploadFileTracker: fileUUID: 85F13EAF-035C-4E94-B571-F65EC9394A71; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true); mimeType: text; uploadCopy: true; deletedLocally: nil; deletedOnServer: nil

File group 3C66CDD4-DCBF-478B-BDA2-94BAC12F0571: UploadObjectTracker: fileGroupUUID: 3C66CDD4-DCBF-478B-BDA2-94BAC12F0571; v0Upload: Optional(true); batchUUID: 04353B49-2BFC-43AE-A9BA-E87AEB06D22B; deletedLocally: Optional(false); deletedOnServer: Optional(false) UploadFileTracker: fileUUID: 7A57C89F-73E4-4E97-9B2B-DA6CAB954215; fileVersion: nil; status: uploading; uploadIndex: 1; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true); mimeType: text; uploadCopy: true; deletedLocally: nil; deletedOnServer: nil UploadFileTracker: fileUUID: FAE1DD16-6354-4814-BC6A-0AF8DFD52340; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(true); mimeType: text; uploadCopy: true; deletedLocally: nil; deletedOnServer: nil UploadFileTracker: fileUUID: 5E0531A2-6E86-435E-859B-D4A13F3C7F54; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false); mimeType: url; uploadCopy: false; deletedLocally: nil; deletedOnServer: nil UploadFileTracker: fileUUID: B22449D3-BCAB-4E93-8B4A-74DCFC2E6C34; fileVersion: nil; status: uploading; uploadIndex: 4; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false); mimeType: jpeg; uploadCopy: false; deletedLocally: nil; deletedOnServer: nil

crspybits commented 3 years ago

Rod just supplied me screen grabs of the two albums that are having issues -- the chicken album and the random album. I see no items there that Rod added that are indicating no main image. Which is what I would have expected given the other debugging info so far.

This suggests that for some reason some files cannot be accessed in UploadFileTracker's in iOSBasics where those apparently same files can still be accessed in the Neebla app. This suggests the need for additional debugging info-- Debugging output in Neebla that checks for files that cannot be accessed there. And then I can compare these results to what I have so far in this issue.

crspybits commented 3 years ago

SpecificServerFileModels's:

ServerFileModel: fileUUID: 75C95CC9-BF03-4B1D-AD2D-C5B1BE30AD11; url: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.8731E8E6-538A-4B8B-A00E-2B46E409160A.jpg); nonRelativeURL: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.8731E8E6-538A-4B8B-A00E-2B46E409160A.jpg); canReadFile: Optional(true)

UploadFileTracker: fileUUID: 75C95CC9-BF03-4B1D-AD2D-C5B1BE30AD11; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false); mimeType: jpeg; uploadCopy: false; deletedLocally: nil; deletedOnServer: nil; url: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.1290DD3E-3C49-4B27-9C4C-E5DC8D97A127.jpg); nonRelativeURL: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.1290DD3E-3C49-4B27-9C4C-E5DC8D97A127.jpg)

ServerFileModel: fileUUID: C0F990AD-8E46-46AE-A97B-3D3270F0EF78; url: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.7AECB75A-ED5C-4E61-B36D-82E274CD7485.jpg); nonRelativeURL: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.7AECB75A-ED5C-4E61-B36D-82E274CD7485.jpg); canReadFile: Optional(true)

UploadFileTracker: fileUUID: C0F990AD-8E46-46AE-A97B-3D3270F0EF78; fileVersion: nil; status: uploading; uploadIndex: 2; uploadCount: 3; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false); mimeType: jpeg; uploadCopy: false; deletedLocally: nil; deletedOnServer: nil; url: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.3EF82257-FF98-4A45-B64E-2D1C48216628.jpg); nonRelativeURL: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.3EF82257-FF98-4A45-B64E-2D1C48216628.jpg)

ServerFileModel: fileUUID: 5E0531A2-6E86-435E-859B-D4A13F3C7F54; url: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.B3B4EDB9-F2C0-430F-B4E5-2F8BFA6AFAC2.url); nonRelativeURL: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.B3B4EDB9-F2C0-430F-B4E5-2F8BFA6AFAC2.url); canReadFile: Optional(true)

UploadFileTracker: fileUUID: 5E0531A2-6E86-435E-859B-D4A13F3C7F54; fileVersion: nil; status: uploading; uploadIndex: 3; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false); mimeType: url; uploadCopy: false; deletedLocally: nil; deletedOnServer: nil; url: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.963BE3AA-F60E-46D9-AC98-1FB579FF5679.url); nonRelativeURL: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.963BE3AA-F60E-46D9-AC98-1FB579FF5679.url)

ServerFileModel: fileUUID: B22449D3-BCAB-4E93-8B4A-74DCFC2E6C34; url: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.66242889-39CF-41C6-BF33-99FB6D8FC0FF.jpg); nonRelativeURL: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.66242889-39CF-41C6-BF33-99FB6D8FC0FF.jpg); canReadFile: Optional(true)

UploadFileTracker: fileUUID: B22449D3-BCAB-4E93-8B4A-74DCFC2E6C34; fileVersion: nil; status: uploading; uploadIndex: 4; uploadCount: 4; expiry: Optional(2021-08-11 04:17:00 +0000); canReadFile: Optional(false); mimeType: jpeg; uploadCopy: false; deletedLocally: nil; deletedOnServer: nil; url: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.12CF6E9C-9139-4218-978B-210BCE6D3B82.jpg); nonRelativeURL: Optional(file:///private/var/mobile/Containers/Shared/AppGroup/8D71FCAB-402E-4820-843E-564B0BEAD8CD/Documents/objects/Neebla.12CF6E9C-9139-4218-978B-210BCE6D3B82.jpg)

In each case iOSBasics has a different file URL for the file. It should be immutable, being a reference to the same file as in Neebla, so not sure how it has changed. I have also confirmed that in Neebla, the file still exists.

crspybits commented 3 years ago

I think I've figured out how these file names changed in Neebla. The uploads hadn't yet been recorded as completed in iOSBasics (the SDK). But they actually had finished uploading on the server. When the SDK did a file index request, it got the information about these files. Neebla requested a download of the file. The SDK method objectNeedsDownloadHelper, at the time, would allow a file that was currently being uploaded to also be reported as needing download. The download replaced the existing file in Neebla, removing the prior file. Thus the prior file reference that the SDK was using in its upload was no longer valid.

crspybits commented 3 years ago

I have now added some changes to iOSBasics so that files don't download when they are currently uploading.

But: Now, how to fix this specific situation for Rod? There are four files that have incorrect URL references in iOSBasics, but that have correct references in Neebla itself. The files are actually correctly uploaded, but are not known to be uploaded by the SDK.

crspybits commented 3 years ago

Recent debug output also revealed:

Pending Deletions: UploadDeletionTracker: uuid: C66C55C8-FDBA-4F10-97C1-D3782DBB715B; deletionType: fileGroupUUID; status: deleting; UploadDeletionTracker: uuid: 9692F0FF-8CD4-4E57-B80A-7936B8DC15D0; deletionType: fileGroupUUID; status: deleting;

So, it seems clear we need expiry dates on these trackers too. And the ability to retry them.

If a deletion has already been carried out, how does the server respond on a retry?

crspybits commented 3 years ago

How does Neebla handle deletions? Does it delete the files locally, and then make the request to iOSBasics? Or the other way around?

This is the code in Neebla:

    private func deleteObject() -> Bool {
        do {
            let pushNotificationText = try PushNotificationMessage.forDeletion(of: object)

            // Do the SyncServer call first; it's the most likely to fail of these two.
            try Services.session.syncServer.queue(objectDeletion: object.fileGroupUUID, pushNotificationMessage: pushNotificationText)
            // The actual local deletion of files occurs after the deletion request is completed on the server, and the next index update occurs.
            try object.update(setters: ServerObjectModel.deletedField.description <- true)
        } catch let error {
            logger.error("\(error)")
            return false
        }

        return true
    }

When displaying album items, only items for which ServerObjectModel.deletedField.description == true are used.

crspybits commented 3 years ago

We're going to use the following rules for queuing deletions, uploads and downloads of specific file groups.

1) Deletions take priority over everything else, except pending uploads and downloads are allowed to complete. Queuing a deletion for an object means that additional uploads or downloads for that object cannot be queued. A deletion will be dequeued and performed once there are no uploads and downloads remaining for that object.

2) Uploads take priority over downloads, except active downloads are allowed to finish. Because the server establishes the source of truth, it's important we get data to the server. If you attempt to do an upload and there is an active download for that object, the upload is queued. The uploads will not be moved to an active state until there is no download in an active state for the object. You cannot do an upload or queue it if there is a deletion for that object queued.

3) Downloads are lowest priority. If there are any uploads (active or inactive) queued for the object, the download will be queued. Downloads for an object are never moved to an active state if that object has active or queued uploads. You cannot do a download or queue it if there is a deletion queued for that object.

See above for another justification for making downloads lower priority than uploads.

crspybits commented 3 years ago

Recap on the issues that happened:

1) Several uploads failed, maxing out the limit of pending uploads. Not sure exactly why this happened. But then, the remaining uploads were just queued. There was no mechanism to retry uploads that were in an uploading state but that didn't make progress.

2) There was no way as a user to see pending uploads. Rod had lots of pending uploads but didn't know the app was clogged up, not actually uploading them. I've subsequently added a count in the UI of pending uploads/deletions.

3) There was no UI mechanism to present an app initialization failure.

4) I didn't have a mechanism to differentiate between meta data migrations and content migrations with SQLite. This was causing initialization failure.

5) Similarly, pending deletions didn't have a mechanism to retry queued deletions that didn't make progress.

6) I hadn't gotten the prioritization of deletions, uploads, and downloads formalized. [Relatedly, it had been possible for a client to not know an upload was completed, and yet do a download of the same object causing problems.](allow downloading of files currently being uploaded: https://github.com/SyncServerII/Neebla/issues/25#issuecomment-898779555).

7) There was a server change needed to allow retries of v0 uploads. My initial change (server version v1.13.0) supported immutable v0 files. Then I realized that v0 mutable files were needed too-- https://github.com/SyncServerII/Neebla/issues/25#issuecomment-898990676 (server version v1.13.1).

8) Due to another problem, I added expiry logic to downloads and a UI counter to indicate to the user the number of pending downloads.

crspybits commented 3 years ago

So, we got through the first batch of uploads on Rod's device! Yeah! Now there are two sets of uploads remaining.

In each set there is a v0 upload followed by vN uploads. And in each case, the v0 upload has already made it to the server but it's not recorded in the db on the client.

One question: How am I ordering uploads? How do I ensure that v0 uploads get completed first even when there are vN uploads queued also? This is managed by the method toBeStartedNext in iOSBasics-- v0 uploads get carried out first.

crspybits commented 3 years ago

I got Rod to do a refresh while I was looking at the server logs. And I see:

[2021-08-15T04:22:04.971Z] [DEBUG] [CreateRoutes.swift:24 create(routerRequest:)] queryDict: ["fileLabel": "mediaItemAttributes", "objectType": "image", "fileGroupUUID": "5419CF0E-696F-4636-97EB-D758D3088FC6", "uploadCount": "3", "changeResolverName": "MediaItemAttributes", "checkSum": "54d7ebc81ba751163be78cb3077a41ec", "fileUUID": "85F13EAF-035C-4E94-B571-F65EC9394A71", "sharingGroupUUID": "15BB1FAE-D5E5-4694-AE36-04D003802E18", "uploadIndex": "3", "mimeType": "text/plain", "batchUUID": "01D6D804-4C60-41FB-A8D7-5E01E6ACDE47", "batchExpiryInterval": "7200"]
[2021-08-15T04:22:04.971Z] [DEBUG] [RequestMessage+Setup.swift:19 setup(routerRequest:)] Processed NeedingRequestBodyData: bytes: Optional(82)
[2021-08-15T04:22:04.975Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-15T04:22:04.978Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-15T04:22:04.981Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-15T04:22:04.983Z] [DEBUG] [RequestHandler.swift:477 doRemainingRequestProcessing(dbCreds:profileCreds:requestObject:db:profile:accountProperties:sharingGroupUUID:accountDelegate:processRequest:handleResult:)] effectiveOwningUserId: 3
[2021-08-15T04:22:04.986Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-15T04:22:04.989Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-15T04:22:04.992Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-15T04:22:04.996Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-15T04:22:05.002Z] [ERROR] [FileController+UploadFile.swift:57 finish(_:params:)] fileGroupUUID given for vN upload.
[2021-08-15T04:22:05.004Z] [ERROR] [RequestHandler.swift:73 failWithError(failureResult:)] fileGroupUUID given for vN upload.
[2021-08-15T04:22:05.004Z] [INFO] [RequestHandler.swift:161 endWith(clientResponse:)] REQUEST /UploadFile: ABOUT TO END ...
[2021-08-15T04:22:05.004Z] [INFO] [RequestHandler.swift:165 endWith(clientResponse:)] REQUEST /UploadFile: STATUS CODE: internalServerError
[2021-08-15T04:22:05.004Z] [INFO] [RequestHandler.swift:170 endWith(clientResponse:)] REQUEST /UploadFile: COMPLETED
crspybits commented 3 years ago

It looks like isDuplicateV0Upload isn't matching on the server.

In FileIndex, the lastUploadedCheckSum is: 13396d28509f9488b28b12d7e9416416 which clearly doesn't match that in the upload.

Hmmm. I see for vN uploads that the lastUploadedCheckSum is updated in the FileIndex when applying mutations in the deferred upload.

crspybits commented 3 years ago

We now have a download issue. I've added expiries to the download trackers, but I'm not sure that was actually the best way to go. I'm seeing this issue on the server:

[2021-08-16T02:35:16.725Z] [DEBUG] [RequestHandler.swift:477 doRemainingRequestProcessing(dbCreds:profileCreds:requestObject:db:profile:accountProperties:sharingGroupUUID:accountDelegate:processRequest:handleResult:)] effectiveOwningUserId: 3
[2021-08-16T02:35:16.726Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-16T02:35:16.728Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-16T02:35:16.729Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-16T02:35:16.732Z] [DEBUG] [Repository.swift:124 lookup(key:modelInit:)] Found result!
[2021-08-16T02:35:16.734Z] [DEBUG] [Repository.swift:109 lookup(key:modelInit:)] No object found!
[2021-08-16T02:35:16.734Z] [ERROR] [FileController+DownloadFile.swift:103 downloadFile(params:)] Expected file version Optional(1) was not the same as the actual version Optional(5)
[2021-08-16T02:35:16.735Z] [ERROR] [RequestHandler.swift:73 failWithError(failureResult:)] Expected file version Optional(1) was not the same as the actual version Optional(5)
[2021-08-16T02:35:16.735Z] [INFO] [RequestHandler.swift:161 endWith(clientResponse:)] REQUEST /DownloadFile: ABOUT TO END ...
[2021-08-16T02:35:16.735Z] [INFO] [RequestHandler.swift:165 endWith(clientResponse:)] REQUEST /DownloadFile: STATUS CODE: internalServerError
[2021-08-16T02:35:16.735Z] [INFO] [RequestHandler.swift:170 endWith(clientResponse:)] REQUEST /DownloadFile: COMPLETED

What appears to be happening is that the download is really old. And the old version of the file is no longer available. It seems like a better strategy for these downloads would be to delete them and let them retry again as needed. Since downloads are naturally regenerated this should work.

crspybits commented 3 years ago

Well, perhaps it not the best, but I have prior logic that removes downloads that have been retried too many times. I'm going to leave this as it stands.