Timed out waiting for `pkg` to be available in registry `cargo-http-registry`

[StackOverflowExcept1on]

The registry does not respond within 1 minute to request from cargo. My cargo config looks like this:

registry = { default = "cargo-http-registry" }
registries = { cargo-http-registry = { index = "http://127.0.0.1:34499/git", token = "token" } }
net = { git-fetch-with-cli = true }

    Packaged 9 files, 67.0KiB (13.4KiB compressed)
   Uploading gcore v1.5.0-9e2c2f54a (/gear/gcore)
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] parsed 6 headers
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body is content-length (15409 bytes)
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; method=PUT path=/api/v1/crates/new version=HTTP/1.1
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60216
[2024-08-15T10:11:13Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body completed
[2024-08-15T10:11:13Z INFO  cargo_http_registry::serve] request status: success
[2024-08-15T10:11:13Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 116 bytes
    Uploaded gcore v1.5.0-9e2c2f54a to registry `cargo-http-registry`
note: waiting for `gcore v1.5.0-9e2c2f54a` to be available at registry `cargo-http-registry`.
You may press ctrl-c to skip waiting; the crate should be available shortly.

[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] parsed 7 headers
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; method=GET path=/git/info/refs version=HTTP/1.1
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60222
[2024-08-15T10:11:13Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 184 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 59 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] parsed 6 headers
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; method=GET path=/git/HEAD version=HTTP/1.1
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60222
[2024-08-15T10:11:13Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 184 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 23 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] parsed 4 headers
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; method=GET path=/git/objects/02/b5fd6f7d6cd5e09617c4e8df4917d6de8e5709 version=HTTP/1.1
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60222
[2024-08-15T10:11:13Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 185 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 206 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] parsed 4 headers
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; method=GET path=/git/objects/5e/5223d6801820b79ac2f3ecb0d73eb698bd5b1f version=HTTP/1.1
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60222
[2024-08-15T10:11:13Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 185 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 849 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] parsed 4 headers
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; method=GET path=/git/objects/f0/962157263a32ee7f161f4c4fae88fb2ac5ab4f version=HTTP/1.1
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60222
[2024-08-15T10:11:13Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 184 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 44 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] parsed 3 headers
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; method=GET path=/git/objects/18/9391b76d93be37b38763073cf261947b205b1d version=HTTP/1.1
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60230
[2024-08-15T10:11:13Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 187 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] parsed 3 headers
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 8192 bytes
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; method=GET path=/git/objects/52/811245bf1c801a658905f69242190279f0b3ae version=HTTP/1.1
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60222
[2024-08-15T10:11:13Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 5514 bytes
[2024-08-15T10:11:13Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 184 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 50 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] parsed 3 headers
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; method=GET path=/git/objects/79/ac96df0db319606ebfbe9a014aa4a26734ed29 version=HTTP/1.1
[2024-08-15T10:11:13Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60230
[2024-08-15T10:11:13Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:13Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 185 bytes
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::io] flushed 438 bytes
From http://127.0.0.1:34499/git
   fbe2d87..02b5fd6             -> origin/HEAD
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] read eof
[2024-08-15T10:11:13Z DEBUG hyper::proto::h1::conn] read eof
[2024-08-15T10:11:14Z DEBUG hyper::proto::h1::io] parsed 7 headers
[2024-08-15T10:11:14Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:14Z INFO  warp::filters::trace] request; method=GET path=/git/info/refs version=HTTP/1.1
[2024-08-15T10:11:14Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60242
[2024-08-15T10:11:14Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:14Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:14Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:14Z DEBUG hyper::proto::h1::io] flushed 184 bytes
[2024-08-15T10:11:14Z DEBUG hyper::proto::h1::io] flushed 59 bytes
[2024-08-15T10:11:14Z DEBUG hyper::proto::h1::io] parsed 6 headers
[2024-08-15T10:11:14Z DEBUG hyper::proto::h1::conn] incoming body is empty
[2024-08-15T10:11:14Z INFO  warp::filters::trace] request; method=GET path=/git/HEAD version=HTTP/1.1
[2024-08-15T10:11:14Z INFO  warp::filters::trace] request; remote.addr=127.0.0.1:60242
[2024-08-15T10:11:14Z DEBUG warp::filters::trace] received request
[2024-08-15T10:11:14Z INFO  warp::filters::trace] processing request
[2024-08-15T10:11:14Z INFO  warp::filters::trace] finished processing with success status=200
[2024-08-15T10:11:14Z DEBUG hyper::proto::h1::io] flushed 184 bytes
[2024-08-15T10:11:14Z DEBUG hyper::proto::h1::io] flushed 23 bytes
[2024-08-15T10:11:14Z DEBUG hyper::proto::h1::conn] read eof
[2024-08-15T10:11:15Z DEBUG hyper::proto::h1::io] parsed 7 headers
[2024-08-15T10:11:15Z DEBUG hyper::proto::h1::conn] incoming body is empty

warning: timed out waiting for `gcore v1.5.0-9e2c2f54a` to be available in registry `cargo-http-registry`
note: the registry may have a backlog that is delaying making the crate available. The crate should be available soon.
[2024-08-15T10:12:13Z DEBUG hyper::proto::h1::conn] read eof

[d-e-s-o]

Interestingly this timeout is also hit when using direct file system access as opposed to HTTP. So that would rule out any issues related to caching.

[d-e-s-o]

I think the issue comes down to cargo failing to validate some entry:

   0.732203346s  INFO main:exec: cargo::sources::registry::index: failed to parse "de/mo/demo-a" registry package: optional dependency `renamed_once_cell` is not included in any feature
Make sure that `dep:renamed_once_cell` is included in one of features in the [features] table.

It ends up discarding it more or less silently, which means it won't show up in the summaries that it queries every second
https://github.com/rust-lang/cargo/blob/ffa9cf99a594e59032757403d4c780b46dc2c43a/src/cargo/ops/registry/publish.rs#L258

https://github.com/rust-lang/cargo/blob/ffa9cf99a594e59032757403d4c780b46dc2c43a/src/cargo/sources/registry/index/mod.rs#L739

[StackOverflowExcept1on]

I fixed this issue by removing the unused dependency and feature in our code, but when publish the package to crates-io I didn't get this issue. This still says that cargo-http-registry is quite unstable.

[d-e-s-o]

If you can provide crate name and version that you published to crates.io as well as the contents of the local registry after you tried publishing the same versioned crate to it, we may be able to get to the bottom of it.

[StackOverflowExcept1on]

I tried to publish the crate gcore, which has the feature dep:codec (which is actually a renamed dependency of parity-scale-codec). The contents of the crates.io registry: https://github.com/rust-lang/crates.io-index/blob/master/gc/or/gcore, which is slightly different from the local registry. In particular, it does not have features2.

crates.io:

{
  "name": "gcore",
  "vers": "1.5.0",
  "deps": [
    {
      "name": "codec",
      "req": "^3.6.4",
      "features": [],
      "optional": true,
      "default_features": false,
      "target": null,
      "kind": "normal",
      "package": "parity-scale-codec"
    },
    {
      "name": "galloc",
      "req": "^1.5.0",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "dev"
    },
    {
      "name": "gear-core-errors",
      "req": "^1.5.0",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "normal"
    },
    {
      "name": "gear-stack-buffer",
      "req": "^1.5.0",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "normal"
    },
    {
      "name": "gprimitives",
      "req": "^1.5.0",
      "features": [],
      "optional": false,
      "default_features": false,
      "target": null,
      "kind": "normal"
    },
    {
      "name": "gsys",
      "req": "^1.5.0",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "normal"
    },
    {
      "name": "hex-literal",
      "req": "^0.4.1",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "dev"
    }
  ],
  "cksum": "c0bdb11c2fe9c5e92615a7ea4b188408bfbe557c47809c7adeefc018efdf707d",
  "features": {
    "debug": []
  },
  "features2": {
    "codec": [
      "dep:codec",
      "gear-core-errors/codec",
      "gprimitives/codec"
    ]
  },
  "yanked": false,
  "rust_version": "1.80",
  "v": 2
}

cat /tmp/cargo-http-registry/gc/or/gcore | jq

{
  "name": "gcore",
  "vers": "1.5.0-b710fb843",
  "deps": [
    {
      "name": "codec",
      "req": "^3.6.4",
      "features": [],
      "optional": true,
      "default_features": false,
      "target": null,
      "kind": "normal",
      "registry": "https://github.com/rust-lang/crates.io-index",
      "package": "parity-scale-codec"
    },
    {
      "name": "gear-core-errors",
      "req": "^1.5.0-b710fb843",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "normal",
      "registry": null,
      "package": null
    },
    {
      "name": "gear-stack-buffer",
      "req": "^1.5.0-b710fb843",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "normal",
      "registry": null,
      "package": null
    },
    {
      "name": "gprimitives",
      "req": "^1.5.0-b710fb843",
      "features": [],
      "optional": false,
      "default_features": false,
      "target": null,
      "kind": "normal",
      "registry": null,
      "package": null
    },
    {
      "name": "gsys",
      "req": "^1.5.0-b710fb843",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "normal",
      "registry": null,
      "package": null
    },
    {
      "name": "galloc",
      "req": "^1.5.0-b710fb843",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "dev",
      "registry": null,
      "package": null
    },
    {
      "name": "hex-literal",
      "req": "^0.4.1",
      "features": [],
      "optional": false,
      "default_features": true,
      "target": null,
      "kind": "dev",
      "registry": "https://github.com/rust-lang/crates.io-index",
      "package": null
    }
  ],
  "cksum": "ed514b238616c25adaa68fe08846241444b10492200e2e42c860456058af8e88",
  "features": {
    "codec": [
      "gear-core-errors/codec",
      "gprimitives/codec"
    ],
    "debug": [],
    "ethexe": [
      "gsys/ethexe"
    ]
  },
  "yanked": false,
  "links": null
}

I also described a minimal example here: rust-lang/cargo#14399 (comment), but I was told that the absence of features2 is normal

[StackOverflowExcept1on]

I don't see much difference with crates-io. Some fields are in different order, some fields are explicitly set to null (we can try to change the order and add #[serde(skip_serializing_if = "Option::is_none")]). The ethexe feature was added to our unreleased build, but not in version 1.5.0, so don't pay attention to it. Only difference that really makes sense is the absence of dep:codec and features2 in cargo-http-registry. Also on crates-io there seems to be some sorting by certain dependency fields.

I also tried to replicate crates-io behavior locally, but I couldn't get dep:codec from package publish data. Features were split into features and features2, but dep:codec was still missing. It's possible that crates-io parses Cargo.toml or something like that.
https://github.com/rust-lang/crates.io/blob/9a026aa8838c858a5ce5c4389331007e8561152c/src/models/krate.rs#L504

[d-e-s-o]

Ah okay, thanks for the analysis. Very strange. Yeah, I don't think ordering matters. Same for null. I may try debug further locally at some point, if Cargo folks don't respond.