[Bug]: Very recently updated mods fail to install with corrupted download message in eastern hemisphere

SunSerega commented 11 months ago

Is there an existing issue for this?

[X] I have searched the existing issues

Operating System

Win10

CKAN Version

1.34.2

Games

KSP 2

Game Version

0.2

Did you make any manual changes to your game folder (i.e., not via CKAN)?

Nope

Describe the bug

About to upgrade:
 * Upgrade: Patch Manager 0.5.0 to 0.6.0 (spacedock.info, 247.0 KiB)
Downloading "https://spacedock.info/mod/3482/Patch%20Manager/download/0.6.0"
Finished downloading PatchManager 0.6.0, validating and storing to cache...
Trying to install PatchManager 0.6.0, but it's not downloaded or download is corrupted
Error during installation!
If the above message indicates a download error, please try again. Otherwise, please open an issue for us to investigate.
If you suspect a metadata problem: https://github.com/KSP-CKAN/NetKAN/issues/new/choose
If you suspect a bug in the client: https://github.com/KSP-CKAN/CKAN/issues/new/choose

If I launch using this command:

ckan --show-console --debug

Last few lines:

21309 [4] INFO CKAN.ModuleInstaller (null) - Removed PatchManager
21312 [4] DEBUG CKAN.NetFileCache (null) - Checking cache for https://spacedock.info/mod/3482/Patch Manager/download/0.6.0
21313 [4] DEBUG CKAN.NetFileCache (null) - Rebuilding cache index
21315 [4] DEBUG CKAN.NetFileCache (null) - Found file C:\Users\SunMachine\AppData\Local\CKAN\downloads\3AFBD5A2-PatchManager-0.6.0.zip
21316 [4] DEBUG CKAN.NetFileCache (null) - Found stale file, deleting it
21316 [20] DEBUG CKAN.NetFileCache (null) - File system watcher event fired
21317 [20] DEBUG CKAN.NetFileCache (null) - Purging cache index
21329 [4] INFO CKAN.Registry (null) - Aborted transaction, rolling back in-memory registry changes.

I couldn't catch this .zip file being created - so I presume it's deleted almost instantly after the download finishes.

Steps to reproduce

I just click "Update all" and "Apply". The issue at least doesn't go away after the restart, but I haven't tried completely deleting and re-adding this mod, in case you want me to test something in the current glitched state. And I now don't have enough disk space to make another 30 GB copy...

Relevant log output

No response

HebaruSan commented 11 months ago

CKAN Version

1.32.2

Hi @SunSerega, thanks for the report. Please upgrade to the latest CKAN, since bugs on older versions may already be fixed:

https://github.com/KSP-CKAN/CKAN/releases/tag/v1.34.2

SunSerega commented 11 months ago

I mistyped. I have autoupdate on, so it is in fact v1.34.2.

SunSerega commented 11 months ago

Btw, you can make an issue creation link that pre-fills some fields with known info, like this: https://github.com/KSP-CKAN/CKAN/issues/new?assignees=&labels=Bug&projects=&template=ckan_bug.yml&title=%5BBug%5D%3A+&operating-system=Win10&ckan-version=1.34.2

HebaruSan commented 11 months ago

More to the point, there's a link in GitHub that you can use to fix errors like that:

SunSerega commented 11 months ago

I was sure I already edited it to be right back then. Meanwhile, the problem stopped reproducing, but I guess it's still a good idea to figure out why that happened...

HebaruSan commented 11 months ago

OK, "Found stale file" means that the timestamp of your file on disk was older than that of the file on the remote host. Which is surprising, since that download does not appear to have been changed by the author since it was uploaded.

Would you mind sharing your time zone? SpaceDock uses UTC or close to it, so that might provide a clue as to what's happening.

HebaruSan commented 11 months ago

Notably, this was filed very shortly after that mod was added, then stopped happening later, which is consistent with some sort of time zone related timestamp mix-up.

HebaruSan commented 11 months ago

That mod's SpaceDock API link is here:

https://spacedock.info/api/mod/3482

The timestamp for 0.6.0 is:

      "created": "2023-12-21T20:57:23.660963+00:00",

One possibility is that this is in the future of when it was uploaded, so it appears newer than it actually is. Tricky to determine, but comparing with the commit times in CKAN-meta might do it...

https://github.com/KSP-CKAN/KSP2-CKAN-meta/blob/main/PatchManager/PatchManager-0.6.0.ckan

... It looks like everything is fine in that respect. 20:57 UTC is just over an hour earlier than the when .ckan file was added, so it should not have been possible to end up with a local timestamp older than that.

SunSerega commented 11 months ago

Yeah, that makes sense. What do you think about running the same check before saving the file to disk, so that at least users would see the correct error?

P.S. Currently I'm in UTC+3

HebaruSan commented 11 months ago

@SunSerega, is your system clock set to something weird? As I just added to the above comment, the server timestamps all seem to be in order, so we'll have to look elsewhere for the source of the discrepancy.

SunSerega commented 11 months ago

No, it's set automatically. But I'm in a timezone where it's UTC+2 in the summer and UTC+3 in winter. That's what I meant by "currently", idk if this is connected.

SunSerega commented 11 months ago

Actually, no, sorry, it's the other way around - UTC+3 in the summer and UTC+2 currently...

HebaruSan commented 11 months ago

Just received reports on Discord of other users having this issue with SpaceWarp 1.7.0 in UTC+1, but it doesn't reproduce for me (UTC-6). So my guess is that there's something with time zone conversions that breaks in the east and not the west.

HebaruSan commented 11 months ago

The timestamp of the cached file on disk loads correctly and accurately represents when the file was created.

The remote timestamp, on the other hand, is being affected by two serious design defects in different components:

When Newtonsoft.Json (de-)serializes a UTC timestamp, such as CkanModule.release_date, it does not preserve the time zone as-is or convert it to UTC, as any reasonable programmer would expect. Instead, it converts to local time!! If you print it, it shows the correct time zone offset, so in theory it has all the info needed to recreate the original timestamp, except...
DateTime has two modes, local and UTC (it is unable to represent a timestamp in any of the ~22 other time zones), and < and > comparison operators. When it compares a local timestamp (which we have for the remote timestamp, see above) to a UTC timestamp (which we have from disk), it does not convert them to the same time zone, even though it has all the information it would need to do so! This means it gives wrong answers unless the calling code uses .ToUniversalTime() carefully and strategically to ensure consistency itself. Something that could have been a guard rail in the library code that handles comparisons, protecting everyone, instead needs to be considered and coded in every single app that needs to work with timestamps. 🤦

Together, these two very surprising choices in the runtime and libraries break this simple line of code for people east of Greenwich:

https://github.com/KSP-CKAN/CKAN/blob/9addf80bd67307366aac512c6ae5dd7b4ef2ad40/Core/Net/NetFileCache.cs#L221-L222

remoteTimestamp is a local timestamp (despite Netkan generating and saving it in UTC originally), so it will be treated as greater than an actually-equivalent-or-slightly-less UTC timestamp returned by File.GetLastWriteTime(file).ToUniversalTime() if the local hour is greater than the UTC hour, i.e. if the time zone offset is negative, i.e. if you're in the eastern hemisphere.

The western hemisphere has the opposite, far less obvious problem. There, remote timestamps are treated as older than they really are, so if a mod author replaces a download, a user re-installing that mod will not get the latest changes if they first downloaded it just a few hours before the replacement.

HebaruSan commented 11 months ago

@SunSerega, thank you so much for the verbose debugging output taken from your computer. This would have been impossible to track down without this line in particular:

21316 [4] DEBUG CKAN.NetFileCache (null) - Found stale file, deleting it

KSP-CKAN / CKAN