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

[thomashoneyman]

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]

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]

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]

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]

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]

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]

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]

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]

I wonder if this logic is at fault?

spago/src/Spago/Registry.purs

Lines 195 to 207 in 82d99ab

	-- we first try reading it from the DB
	liftEffect (Db.getMetadata db name) >>= case _ of
	Just metadata | not fetchingFreshRegistry -> do
	logDebug $ "Got metadata from DB: " <> PackageName.print name
	pure (Right metadata)
	_ -> do
	-- if we don't have it we try reading it from file
	metadataFromFile name >>= case _ of
	Left e -> pure (Left e)
	Right m -> do
	-- and memoize it
	liftEffect (Db.insertMetadata db name m)
	pure (Right m)

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?