Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
3 tasks done
jclab-joseph opened this issue Jun 16, 2023 · 9 comments
Labels
kind/bug A bug in existing code (including security flaws) need/analysis Needs further analysis before proceeding P2 Medium: Good to have, but can wait until someone steps up

Comments

@jclab-joseph
Copy link

jclab-joseph commented Jun 16, 2023

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

  • 172.30.42.164 : Pod IP
$ 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

  • 172.30.42.169 : Pod IP
  • 10.XXX.XXX.200 : Service IP (external accessible)
  • 10.SSS.SSS.200 : Node IP that has target IPFS Pod
$  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
@jclab-joseph jclab-joseph added kind/bug A bug in existing code (including security flaws) need/triage Needs initial labeling and prioritization labels Jun 16, 2023
@lidel
Copy link
Member

lidel commented Jul 3, 2023

@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 libp2p/specs#489

@jclab-joseph
Copy link
Author

@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
Copy link
Member

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
Copy link
Contributor

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

@aschmahmann aschmahmann added need/analysis Needs further analysis before proceeding P2 Medium: Good to have, but can wait until someone steps up and removed need/triage Needs initial labeling and prioritization labels Jul 10, 2023
@marten-seemann
Copy link
Member

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
Copy link
Contributor

Jorropo commented Jul 31, 2023

@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
Copy link
Member

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

@Jorropo
Copy link
Contributor

Jorropo commented Jul 31, 2023

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

@marten-seemann
Copy link
Member

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug A bug in existing code (including security flaws) need/analysis Needs further analysis before proceeding P2 Medium: Good to have, but can wait until someone steps up
Projects
None yet
Development

No branches or pull requests

5 participants