search

ipfs / kubo

An IPFS implementation in Go
https://docs.ipfs.tech/how-to/command-line-quick-start/
Other
16k stars 3k forks source link

accept upgrade error: failed to negotiate security protocol: privnet: could not read full nonce #9967

Open jclab-joseph opened 1 year ago

jclab-joseph commented 1 year ago

Checklist

Installation method

built from source

Version

Kubo version: 0.19.2-afb27ca17-dirty (0.20.0 also same)
Repo version: 13
System version: amd64/linux
Golang version: go1.20.4

Config

{
  "API": {
    "HTTPHeaders": {
      "Access-Control-Allow-Methods": [
        "PUT",
        "POST"
      ],
      "Access-Control-Allow-Origin": [
        "*"
      ]
    }
  },
  "Addresses": {
    "API": "/ip4/0.0.0.0/tcp/5001",
    "Announce": [],
    "AppendAnnounce": [
      "/ip4/10.XXX.XXX.100/tcp/4001"
    ],
    "Gateway": "/ip4/0.0.0.0/tcp/8080",
    "NoAnnounce": [
      "/ip4/100.64.0.0/ipcidr/10",
      "/ip4/169.254.0.0/ipcidr/16",
      "/ip4/172.16.0.0/ipcidr/12",
      "/ip4/192.0.0.0/ipcidr/24",
      "/ip4/192.0.2.0/ipcidr/24",
      "/ip4/198.18.0.0/ipcidr/15",
      "/ip4/198.51.100.0/ipcidr/24",
      "/ip4/203.0.113.0/ipcidr/24",
      "/ip4/240.0.0.0/ipcidr/4",
      "/ip6/100::/ipcidr/64",
      "/ip6/2001:2::/ipcidr/48",
      "/ip6/2001:db8::/ipcidr/32",
      "/ip6/fc00::/ipcidr/7",
      "/ip6/fe80::/ipcidr/10"
    ],
    "Swarm": [
      "/ip4/0.0.0.0/tcp/4001",
      "/ip4/0.0.0.0/tcp/4002/ws",
      "/ip4/0.0.0.0/udp/4001/quic",
      "/ip4/0.0.0.0/udp/4001/quic-v1",
      "/ip4/0.0.0.0/udp/4001/quic-v1/webtransport"
    ]
  },
  "AutoNAT": {},
  "Bootstrap": [
    "/ip4/10.1.15.250/tcp/4001/p2p/12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8"
  ],
  "DNS": {
    "Resolvers": {}
  },
  "Datastore": {
    ...
  },
  "Discovery": {
    "MDNS": {
      "Enabled": false
    }
  },
  "Experimental": {
    "AcceleratedDHTClient": false,
    "FilestoreEnabled": false,
    "GraphsyncEnabled": false,
    "Libp2pStreamMounting": false,
    "P2pHttpProxy": false,
    "StrategicProviding": false,
    "UrlstoreEnabled": false
  },
  "Gateway": {
    "APICommands": [],
    "HTTPHeaders": {
      "Access-Control-Allow-Headers": [
        "X-Requested-With",
        "Range",
        "User-Agent"
      ],
      "Access-Control-Allow-Methods": [
        "GET"
      ],
      "Access-Control-Allow-Origin": [
        "*"
      ]
    },
    "NoDNSLink": false,
    "NoFetch": false,
    "PathPrefixes": [],
    "PublicGateways": null,
    "RootRedirect": ""
  },
  "Identity": {
    "PeerID": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"
  },
  "Internal": {},
  "Ipns": {
    "RecordLifetime": "",
    "RepublishPeriod": "",
    "ResolveCacheSize": 128
  },
  "Migration": {
    "DownloadSources": [],
    "Keep": ""
  },
  "Mounts": {
    "FuseAllowOther": false,
    "IPFS": "/ipfs",
    "IPNS": "/ipns"
  },
  "Peering": {
    "Peers": null
  },
  "Pinning": {
    "RemoteServices": {}
  },
  "Plugins": {
    "Plugins": null
  },
  "Provider": {
    "Strategy": ""
  },
  "Pubsub": {
    "DisableSigning": false,
    "Router": ""
  },
  "Reprovider": {},
  "Routing": {
    "Methods": null,
    "Routers": null,
    "Type": "dht"
  },
  "Swarm": {
    "AddrFilters": [
      "/ip4/100.64.0.0/ipcidr/10",
      "/ip4/169.254.0.0/ipcidr/16",
      "/ip4/198.18.0.0/ipcidr/15",
      "/ip4/198.51.100.0/ipcidr/24",
      "/ip4/203.0.113.0/ipcidr/24",
      "/ip4/240.0.0.0/ipcidr/4",
      "/ip6/100::/ipcidr/64",
      "/ip6/2001:2::/ipcidr/48",
      "/ip6/2001:db8::/ipcidr/32",
      "/ip6/fc00::/ipcidr/7",
      "/ip6/fe80::/ipcidr/10"
    ],
    "ConnMgr": {
      "HighWater": 2000
    },
    "DisableBandwidthMetrics": false,
    "DisableNatPortMap": true,
    "RelayClient": {},
    "RelayService": {},
    "ResourceMgr": {
      "Limits": {}
    },
    "Transports": {
      "Multiplexers": {},
      "Network": {},
      "Security": {}
    }
  }
}

Description

Bitswap seems to throw the error "accept upgrade error: failed to negotiate security protocol: privnet: could not read full nonce". But the swarm connection works just fine.

swarm.key is the same.

12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM : Current IPFS Node

$ ipfs id
{
    "ID": "12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM",
    "PublicKey": "...",
    "Addresses": [
        "/ip4/10.SSS.SSS.100/tcp/4001/p2p/12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM",
        "/ip4/127.0.0.1/tcp/4001/p2p/12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM",
        "/ip4/127.0.0.1/tcp/4002/ws/p2p/12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM"
    ],
    "AgentVersion": "kubo/0.19.2/afb27ca17-dirty/docker",
    "ProtocolVersion": "ipfs/0.1.0",
    "Protocols": [
        "/ipfs/bitswap",
        "/ipfs/bitswap/1.0.0",
        "/ipfs/bitswap/1.1.0",
        "/ipfs/bitswap/1.2.0",
        "/ipfs/id/1.0.0",
        "/ipfs/id/push/1.0.0",
        "/ipfs/lan/kad/1.0.0",
        "/ipfs/ping/1.0.0",
        "/libp2p/autonat/1.0.0",
        "/libp2p/circuit/relay/0.2.0/stop",
        "/x/"
    ]
}

$ ipfs swarm peers
/ip4/10.XXX.XXX.200/tcp/4001/p2p/12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8
  /ipfs/bitswap
  /ipfs/lan/kad/1.0.0

$ ipfs swarm connect /ip4/10.XXX.XXX.200/tcp/4001/p2p/12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8
connect 12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8 success

$ ipfs ping 12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8
PING 12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8.
Pong received: time=1.94 ms
Pong received: time=0.59 ms
Pong received: time=1.26 ms
Pong received: time=1.09 ms

12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8 : Target IPFS Node

$  ipfs id
{
    "ID": "12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8",
    "PublicKey": "...",
    "Addresses": [
        "/ip4/10.XXX.XXX.200/tcp/4001/p2p/12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8",
        "/ip4/127.0.0.1/tcp/4001/p2p/12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8",
        "/ip6/::1/tcp/4001/p2p/12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8"
    ],
    "AgentVersion": "kubo/0.19.2/afb27ca17-dirty/docker",
    "ProtocolVersion": "ipfs/0.1.0",
    "Protocols": [
        "/ipfs/bitswap",
        "/ipfs/bitswap/1.0.0",
        "/ipfs/bitswap/1.1.0",
        "/ipfs/bitswap/1.2.0",
        "/ipfs/id/1.0.0",
        "/ipfs/id/push/1.0.0",
        "/ipfs/lan/kad/1.0.0",
        "/ipfs/ping/1.0.0",
        "/libp2p/autonat/1.0.0",
        "/libp2p/circuit/relay/0.2.0/stop",
        "/x/"
    ]
}

$ ipfs swarm peers -v
/ip4/172.30.42.164/tcp/48094/p2p/12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM 13.644582ms inbound
  /ipfs/bitswap
  /ipfs/lan/kad/1.0.0

$ ipfs ping 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM
PING 12D3KooWMfT7tYd4Az7iQVz5RFL2voFkZBkf4Z9J2TXnD7MqNijM.
Pong received: time=2.15 ms
Pong received: time=0.74 ms
Pong received: time=1.11 ms

Log

02:46:13.384Z   DEBUG   basichost   basic/basic_host.go:335 failed to fetch local IPv6 address  {"error": "no route found for ::"}
02:46:15.801Z   DEBUG   cmds/http   http/handler.go:90  incoming API request: /repo/stat?size-only=true
02:46:16.673Z   DEBUG   cmds/http   http/handler.go:90  incoming API request: /ls?arg=QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A&encoding=json&resolve-type=true&size=true&stream-channels=true
02:46:16.674Z   DEBUG   blockservice    go-blockservice@v0.5.1/blockservice.go:247  Blockservice: Searching bitswap
02:46:16.674Z   DEBUG   bitswap getter/getter.go:86 Bitswap.GetBlockRequest.Start   {"cid": "QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A"}
02:46:16.674Z   INFO    bs:sess session/session.go:460  No peers - broadcasting {"session": 46025, "want-count": 1}
02:46:16.675Z   DEBUG   bs:sess session/session.go:467  broadcastWantHaves  {"session": 46025, "cids": [{"/":"QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A"}]}
02:46:17.369Z   DEBUG   upgrader    upgrader/listener.go:109    listener <stream.Listener[TCP] /ip4/0.0.0.0/tcp/4001> got connection: /ip4/172.30.42.164/tcp/4001 <---> /ip4/10.SSS.SSS.200/tcp/48570
02:46:17.370Z   DEBUG   upgrader    upgrader/listener.go:125    accept upgrade error: failed to negotiate security protocol: privnet: could not read full nonce (/ip4/172.30.42.164/tcp/4001 <--> /ip4/10.SSS.SSS.200/tcp/48570)
02:46:17.675Z   DEBUG   bs:sess session/session.go:467  broadcastWantHaves  {"session": 46025, "cids": [{"/":"QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A"}]}
02:46:17.675Z   DEBUG   bs:sess session/session.go:361  FindMorePeers   {"session": 46025, "cid": "QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A", "pending": 1}
02:46:17.675Z   DEBUG   bitswap providerquerymanager/providerquerymanager.go:329    New Provider Query on cid: QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A
02:46:17.676Z   DEBUG   bitswap providerquerymanager/providerquerymanager.go:234    Beginning Find Provider Request for cid: QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A
02:46:17.676Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:432    getChannelOrErrorParallel: returning channel
02:46:17.676Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:332    getChannelOrErrorParallel: starting execution for router &{0xc0062a7500 0xc0064f4000} with timeout 0s and ignore errors true
02:46:17.676Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:349    getChannelOrErrorParallel: calling router function for router &{0xc0062a7500 0xc0064f4000} with timeout 0s and ignore errors true
02:46:17.676Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/routing.go:479    finding providers   {"cid": "QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A", "mh": "bciqhujsvhjemmvv5x6bldnlsuriyneeqphcvlkkvhaaswvewuq2vaiy"}
02:46:17.677Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/routing.go:479    finding providers   {"cid": "QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A", "mh": "bciqhujsvhjemmvv5x6bldnlsuriyneeqphcvlkkvhaaswvewuq2vaiy"}
02:46:17.677Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:375    getChannelOrErrorParallel: getting channel value for router &{0xc0062a7500 0xc0064f4000} with timeout 0s and ignore errors true closed channel: true
02:46:17.678Z   DEBUG   bitswap providerquerymanager/providerquerymanager.go:329    Received provider (12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8) for cid (QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A)
02:46:17.678Z   DEBUG   bs:sprmgr   sessionpeermanager/sessionpeermanager.go:68 Bitswap: Added peer to session{"session": 46025, "peer": "12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8", "peerCount": 1}
02:46:17.679Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/routing.go:541    1 provider entries
02:46:17.679Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/routing.go:546    got provider: {12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8: [/ip4/10.XXX.XXX.200/tcp/4001 /ip4/127.0.0.1/tcp/4001 /ip6/::1/tcp/4001]}
02:46:17.680Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/routing.go:563    got closer peers: 0 []
02:46:17.680Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/dht.go:650    peer found  {"peer": "12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8"}
02:46:17.680Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:375    getChannelOrErrorParallel: getting channel value for router &{0xc0062a7500 0xc0064f4000} with timeout 0s and ignore errors true closed channel: false
02:46:17.681Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:415    getChannelOrErrorParallel: finished executing all routers 1
02:46:17.681Z   DEBUG   bitswap providerquerymanager/providerquerymanager.go:329    Finished Provider Query on cid: QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A
02:46:18.383Z   DEBUG   basichost   basic/basic_host.go:335 failed to fetch local IPv6 address  {"error": "no route found for ::"}
02:46:18.675Z   DEBUG   bs:sess session/session.go:467  broadcastWantHaves  {"session": 46025, "cids": [{"/":"QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A"}]}
02:46:18.847Z   DEBUG   remotepinning/mfs   ipfs/pinmfs.go:116  pinning loop is awake, 0 remote services
02:46:19.186Z   DEBUG   bs:sess session/session.go:467  broadcastWantHaves  {"session": 46024, "cids": [{"/":"QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A"}]}
02:46:19.689Z   ERROR   core/commands/cmdenv    pin/pin.go:133  context canceled
02:46:19.689Z   DEBUG   cmds    go-ipfs-cmds@v0.8.2/command.go:161  error occured in call, closing with error: context canceled
02:46:19.693Z   DEBUG   blockservice    go-blockservice@v0.5.1/blockservice.go:247  Blockservice: Searching bitswap
02:46:19.693Z   INFO    bs:sess session/session.go:460  No peers - broadcasting {"session": 46026, "want-count": 1}
02:46:20.677Z   DEBUG   bs:sess session/session.go:467  broadcastWantHaves  {"session": 46025, "cids": [{"/":"QmWZUMHKEUohFif1E924T78ZtoHHCyq4GMw5RuaXaK896A"}]}
02:46:20.695Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:432    getChannelOrErrorParallel: returning channel
02:46:20.695Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:332    getChannelOrErrorParallel: starting execution for router &{0xc0062a7500 0xc0064f4000} with timeout 0s and ignore errors true
02:46:20.695Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:349    getChannelOrErrorParallel: calling router function for router &{0xc0062a7500 0xc0064f4000} with timeout 0s and ignore errors true
02:46:20.696Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:375    getChannelOrErrorParallel: getting channel value for router &{0xc0062a7500 0xc0064f4000} with timeout 0s and ignore errors true closed channel: true
02:46:20.697Z   DEBUG   bs:sprmgr   sessionpeermanager/sessionpeermanager.go:68 Bitswap: Added peer to session{"session": 46026, "peer": "12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8", "peerCount": 1}
02:46:20.697Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/routing.go:541    1 provider entries
02:46:20.698Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/routing.go:546    got provider: {12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8: [/ip4/10.XXX.XXX.200/tcp/4001 /ip4/127.0.0.1/tcp/4001 /ip6/::1/tcp/4001]}
02:46:20.698Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/routing.go:563    got closer peers: 0 []
02:46:20.698Z   DEBUG   dht go-libp2p-kad-dht@v0.21.1/dht.go:650    peer found  {"peer": "12D3KooWHfPzNawb4yt5KmYTLu4nDDgtLvp3eXiUsF9dx2cPNBv8"}
02:46:20.698Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:375    getChannelOrErrorParallel: getting channel value for router &{0xc0062a7500 0xc0064f4000} with timeout 0s and ignore errors true closed channel: false
02:46:20.698Z   DEBUG   routing/composable  go-libp2p-routing-helpers@v0.6.2/compparallel.go:415    getChannelOrErrorParallel: finished executing all routers 1
lidel commented 1 year ago

@marten-seemann since this is logged in DEBUG level, I would assume it's a part of expected operations. Is it safe to ignore? Maybe we could adjust this message to be less confusing?

cc https://github.com/libp2p/specs/issues/489

jclab-joseph commented 1 year ago

@lidel oops. Sorry, my explanation was poor. Because of this issue, objects are not shared between the two peers. PINNING on ipfs-cluster fails.

marten-seemann commented 1 year ago

This is where the error occurs: https://github.com/libp2p/go-libp2p/blob/757bf591361cc21b5f7abff4b9afacc7ef58ab30/p2p/net/pnet/psk_conn.go#L31-L37

I believe that when this error occurs, no connection can be established.

aschmahmann commented 1 year ago

@marten-seemann should we consider wrapping the shortErr in the underlying error in the pnet code in go-libp2p to give more clarity here?

marten-seemann commented 1 year ago

There's no need to wrap it. It's only used at this one place. I wouldn't be opposed to modifying the string representation, but I'm also not sure what would be a better message. "could not read full nonce" is pretty much all we know at that point. Maybe prefix is with "psk:"?

Jorropo commented 1 year ago

@marten-seemann "could not read full nonce" is a very correct error message but it's unhelpful if you don't already know about the issue what this means. What about "could not read full nonce (does your PNET keys match ?)" ?

marten-seemann commented 1 year ago

That's not what this error is, see linked code above.

Jorropo commented 1 year ago

Oh so it's the TCP connection being cut short ?

marten-seemann commented 1 year ago

For example. Could be anything that doesn’t allow us to read the full nonce.