Spago database falling out of sync with registry without explicit `spago fetch`

thomashoneyman commented 6 months ago

I'm encountering an issue where the Spago database is out of sync with the registry and therefore I'm failing to install packages.

The full sequence of events I went through is below, but I ended up being able to get what I needed by running spago fetch. I still think there's at least a UX improvement here, though, around when we choose to fetch.

Alright, let's get to the reproduction.

spago: 0.93.29
purs: 0.15.15
package-set (registry) 50.15.0

When installing ordered-collections I got this error:

❌ Couldn't read metadata, reason:
  Didn't find version in the metadata file

This is a bit weird, because the version of ordered-collections in package set 50.15.0 is 3.2.0, and that version has a metadata entry in the registry.

I saw that spago install --verbose ordered-collections fails when accessing ordered-collections in the database:

[     309ms] Got metadata from DB: ordered-collections
[     309ms] 
❌ Couldn't read metadata, reason:
  Didn't find version in the metadata file

So I did some spelunking there and saw that yes, the database is out of sync with the registry and doesn't include this version of ordered_collections. Specifically, I inspected the sqlite database:

➜ sqlite3 /home/trh/.cache/spago-nodejs/spago.v1.sqlite
sqlite> .tables
last_git_pull        package_metadata     package_sets       
package_manifests    package_set_entries

My first thought was the last_git_pull, but that's up to date:

sqlite> SELECT * FROM last_git_pull;
key       date                    
--------  ------------------------
registry  2024-05-11T14:32:22.868Z

My next thought was to check the package_metadata, and indeed ordered-collections@3.2.0 isn't there.

sqlite> SELECT metadata FROM package_metadata WHERE name = 'ordered-collections';
{                                                                                                             
  "published": {
    "<omitted for readability>": {},                                                
    "3.1.1": {                                              
      "bytes": 12306,                                       
      "hash": "sha256-boSYHmlz4aSbwsNN4VxiwCStc0t+y1F7BXmBS+
1JNtI=",                                                    
      "publishedTime": "2023-08-31T07:19:38.918Z",          
      "ref": "v3.1.1"                                       
    }                                                       
  }
}

However, the package set I want is in the package_sets table, and if I inspect its contents in the package_set_entries table I can see ordered-collections@3.2.0 listed.

So then I went to check what Spago reports about the registry entry for the package:

➜ spago registry info ordered-collections
Refreshing the Registry Index...
<snip>
  3.2.0:
    bytes: 12444
    hash: sha256-o9jqsj5rpJmMdoe/zyufWHFjYYFTTsJpgcuCnqCO6PM=
    publishedTime: 2024-03-20T07:21:22.268Z
    ref: v3.2.0

OK, so maybe the registry index hadn't been fetched even though the last_git_pull in the database was recent; perhaps that was just pulling from the registry, not the registry-index. What happens if we install ordered-collections now?

➜ spago install ordered-collections --verbose
<snip>
[     366ms] Got metadata from DB: profunctor
[     366ms] 
❌ Couldn't read metadata, reason:
  Didn't find version in the metadata file

We make it through ordered-collections, but then we hit another package not updated in the database. This isn't tenable. So what's going on with the git repositories themselves? Let's look at the global cache.

Unexpectedly, both the registry and registry-index are up to date:

➜ (registry) git pull
Already up to date.

➜ (registry-index) git pull
Already up to date.

The version of profunctor in 50.15.0 is 6.0.1, so let's see if it's in here:

➜ (registry-index) tail -1 pr/of/profunctor
{"name":"profunctor","version":"6.0.1","license":"BSD-3-Clause","location":{"githubOwner":"purescript","githubRepo":"purescript-profunctor"},"dependencies":{"control":">=6.0.0 <7.0.0","distributive":">=6.0.0 <7.0.0","either":">=6.0.0 <7.0.0","exists":">=6.0.0 <7.0.0","invariant":">=6.0.0 <7.0.0","newtype":">=5.0.0 <6.0.0","prelude":">=6.0.0 <7.0.0","tuples":">=7.0.0 <8.0.0"}}

Yeah, it is. But if we go back to sqlite:

➜ sqlite3 spago.v1.sqlite 
sqlite> select * from package_metadata where name = 'profunctor';
<snip>
profunctor|{
  "published": {
    "<omitted for brevity>": {},
    "6.0.0": {
      "bytes": 6003,
      "hash": "sha256-99NzxFgTr4CGlCSRYG1kShL+JhYbihhHtbOk1/0R5zI=",
      "publishedTime": "2022-04-27T19:24:32.000Z",
      "ref": "v6.0.0"
    }
  }
}

It ain't in there. Something is out of sync between the database and the git repositories. Then I searched a little bit for a way to get Spago to refresh everything and remembered spago fetch. Running that:

➜ spago fetch
Reading Spago workspace configuration...
Refreshing the Registry Index...

✅ Selecting package to build: wat

Downloading dependencies...
Fetching package ordered-collections@3.2.0
Fetching package profunctor@6.0.1
No lockfile found, generating it...
Lockfile written to spago.lock. Please commit this file.

Ah! OK, now everything is up to date. But surely fetch should have been run earlier in this process, like during the install command?

thomashoneyman commented 6 months ago

Encountered a second issue related to this. This time, installing the spec package results in the same error:

[     328ms] Got metadata from DB: spec
[     328ms] 
❌ Couldn't read metadata, reason:
  Didn't find version in the metadata file

However, running spago fetch doesn't help. I get the same error! So, once again I looked at the global cache for the registry and registry-index repositories and confirm that the version in package set 50.15.0 ― spec@7.6.0 — is present in both the registry metadata and registry index.

But then, weirdly:

➜ spago registry info spec
<snip>
  7.5.5:
    bytes: 19330
    hash: sha256-HdyBH7Ys1/m2SdTq3u2u9LdQ4cGeaohWeEMYay2mHdU=
    publishedTime: 2023-09-07T07:15:30.137Z
    ref: v7.5.5
unpublished: {}

The spago registry info command only finds versions up to 7.5.5! Now that is weird, because my package set and checkouts of the registry and registry-index all reflect 7.6.0.

This one is a blocking issue; I can't install spec because I always encounter the "didn't find version in metadata file" error and I haven't found a way around it.

f-f commented 6 months ago

This is another downstream consequence of the whole "lockfiles make spago not hit the network": we used to always pull the registry and refresh the database, but we don't do that as consistently anymore and this creates discrepancies in the DB cache - see #1214 for another example of this.

I'll have a look at this, but in the meantime does removing the lockfile help? This should trigger a proper refresh.

f-f commented 6 months ago

Had a little digging:

every time we pull the Registry we update the package set entries in the DB, so - as you verified - these are always up to date
however, that's not the case for Metadata files: we only insert them in the DB with the insertMetadata function, which is ever only called in Spago.Registry.getMetadata, which we call a few times in the implementation of fetch:
- when we need to write a new lockfile (and here as well)
- and when fetching a package from the Registry

Given the last point, the fact that fetch works and install doesn't is weird - they mostly share the same code path, given that install is fetch + build. The only difference is this case is that we are installing a specific package, and there's a separate code path for that, which is where this must be failing. We don't do anything Registry-related there though. The only other difference is that we invalidate the lockfile when installing new packages, but that should actually help since we'd have to refresh it. Quite puzzling.

thomashoneyman commented 6 months ago

Is there a reason not to fully update the database (ie. including metadata) every time we pull the registry? I was puzzled to see the registry metadata in git was up to date, but not up to date in the database.

thomashoneyman commented 6 months ago

I'll have a look at this, but in the meantime does removing the lockfile help? This should trigger a proper refresh.

I’ll have to verify this when I’m back at that machine; if I remember correctly, no, removing the lock file didn’t make a difference.

f-f commented 6 months ago

Is there a reason not to fully update the database (ie. including metadata) every time we pull the registry?

"Fully update the database" in this case would mean reading all the metadata files potentially every 15 minutes (which is our cutoff for "the registry is fresh enough to not pull"). It's not necessary because very few of them have changed at any given moment, so we read them up on demand, which worked when the lockfile was not delaying updates.

As a side note, I have never encountered this particular instance of the problem - I would be curious to see if we can repro, e.g. fresh cloning of a repo with a lockfile and no local database

thomashoneyman commented 6 months ago

Interesting — I came back to the machine I was testing this on and attempted an install of spec and this time the lockfile was detected as out-of-date, it got regenerated, and the package was installed:

➜ spago install spec
Reading Spago workspace configuration...

✅ Selecting package to build: wat

Refreshing the Registry Index...
Adding 1 package to the config in spago.yaml
Downloading dependencies...
Fetching package spec@7.6.0
Lockfile is out of date (installing new packages), generating it...
Lockfile written to spago.lock. Please commit this file

This is odd because I haven't even accessed this machine since I was testing for this issue. Nothing has changed about its state except for more time elapsing, which makes me think there is some interaction with the 15-minute timer too.

f-f commented 6 months ago

I wonder if this logic is at fault? https://github.com/purescript/spago/blob/82d99ab015e3852e25ab9f8ae36bbce2bf338cdd/src/Spago/Registry.purs#L195-L207

The important bit is that not fetchingFreshRegistry: if we have cached a metadata file, we only go read it if we are outside of that 15 minutes window. I can now see how the bug happens: if you recently pulled the registry, and then go do spago install spec, and no projects recently refreshed the metadata file for spec, then it won't be found in the DB cache.

Not sure how to go at it - maybe we should stat the metadata file and see if it's newer than the copy we have in cache, and then read it if not?

thomashoneyman commented 5 months ago

Encountered this again, but this time without even being in a Spago project at all. When running spago registry package-sets the entries I see are way out of date:

(nix:purescript-overlay-env)$ spago registry package-sets
+---------+------------+----------+
| VERSION | DATE       | COMPILER |
+---------+------------+----------+
(...previous entries omitted)
| 48.2.0  | 2024-01-16 | 0.15.14  |
+---------+------------+----------+

This is showing the latest package set is from Jan 16 2024, but of course we've had many releases since then. So I thought — is this a spago fetch issue again?

(nix:purescript-overlay-env)$ mkdir wat && cd wat && spago init
Initializing a new project...
Refreshing the Registry Index...
Found PureScript 0.15.16, will use package set 51.1.0
Set up a new Spago project.
Try running `spago run`

OK, spago init picked up a later package set. What does spago registry return now?

(nix:purescript-overlay-env)$ spago registry package-sets
+---------+------------+----------+
| VERSION | DATE       | COMPILER |
+---------+------------+----------+
(...previous entries omitted)
| 51.1.0  | 2024-06-05 | 0.15.15  |
+---------+------------+----------+

Now it's picking up all the package set entries.

Zelenya commented 5 months ago

Seems like I bumped into this as well. I've just upgraded to spago-next and migrated a project.

First I ran spago migrate, installed spago-next, ran spago test, and then tried to switch to the new Registry package sets (instead of urls), but I don't know how to get a set "number".

➜ spago --version
0.93.30

➜ spago registry package-sets --latest
+---------+------+----------+
| VERSION | DATE | COMPILER |
+---------+------+----------+
+---------+------+----------+

➜ spago registry package-sets
+---------+------+----------+
| VERSION | DATE | COMPILER |
+---------+------+----------+
+---------+------+----------

`spago fetch` didn't help:

➜ spago fetch
Reading Spago workspace configuration...

✅ Selecting package to build: my-project

Downloading dependencies...
➜ spago registry package-sets --latest
+---------+------+----------+
| VERSION | DATE | COMPILER |
+---------+------+----------+
+---------+------+----------+

After that, in a different random directory

Following @thomashoneyman recommendation, spago init did refresh the index:

➜  test spago init
Initializing a new project...
Refreshing the Registry Index...
Cloning https://github.com/purescript/registry-index.git
Cloning https://github.com/purescript/registry.git
...

➜ spago registry package-sets --latest
+---------+------------+----------+
| VERSION | DATE       | COMPILER |
+---------+------------+----------+
| 10.0.0  | 2023-01-05 | 0.15.4   |
| 20.0.3  | 2023-04-08 | 0.15.7   |
| 27.2.0  | 2023-06-17 | 0.15.8   |
| 29.1.0  | 2023-07-18 | 0.15.9   |
| 43.3.0  | 2023-10-23 | 0.15.10  |
| 46.2.0  | 2023-11-23 | 0.15.12  |
| 47.10.0 | 2023-12-28 | 0.15.13  |
| 50.1.2  | 2024-02-27 | 0.15.14  |
| 51.1.0  | 2024-06-05 | 0.15.15  |
+---------+------------+----------+

f-f commented 5 months ago

@Zelenya this is a related issue, but a different bug 🙂 It is the same issue as #1212, and the fix for that (#1214) was too ad-hoc and missed the bigger picture. There is a more proper fix for this in #1228.

This ticket should stay open because I am still of the opinion that the fix will involve taking care of the bit of code that I described in https://github.com/purescript/spago/issues/1221#issuecomment-2110381624

f-f commented 5 months ago

Released in 0.93.35

purescript / spago