ipfs / kubo

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

bug: failed to establish port mapping: goupnp: error performing SOAP HTTP request #9759

Open SgtPooki opened 1 year ago

SgtPooki commented 1 year ago

Checklist

Installation method

built from source

Version

Kubo version: 0.20.0-dev-1457b4fd4
Repo version: 13
System version: arm64/darwin
Golang version: go1.19

Config

{
  "API": {
    "HTTPHeaders": {}
  },
  "Addresses": {
    "API": "/ip4/127.0.0.1/tcp/5001",
    "Announce": [],
    "AppendAnnounce": [],
    "Gateway": "/ip4/127.0.0.1/tcp/8080",
    "NoAnnounce": [],
    "Swarm": [
      "/ip4/0.0.0.0/tcp/4001",
      "/ip6/::/tcp/4001",
      "/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",
      "/ip6/::/udp/4001/quic",
      "/ip6/::/udp/4001/quic-v1",
      "/ip6/::/udp/4001/quic-v1/webtransport"
    ]
  },
  "AutoNAT": {},
  "Bootstrap": [
    "/dnsaddr/bootstrap.libp2p.io/p2p/QmNnooDu7bfjPFoTZYxMNLWUQJyrVwtbZg5gBMjTezGAJN",
    "/dnsaddr/bootstrap.libp2p.io/p2p/QmQCU2EcMqAqQPR2i9bChDtGNJchTbq5TbXJJ16u19uLTa",
    "/dnsaddr/bootstrap.libp2p.io/p2p/QmbLHAnMoJPWSCR5Zhtx6BHJX9KiKNN6tpvbUcqanj75Nb",
    "/dnsaddr/bootstrap.libp2p.io/p2p/QmcZf59bWwK5XFi76CZX8cbJ4BhTzzA3gU1ZjYZcYW3dwt",
    "/ip4/104.131.131.82/tcp/4001/p2p/QmaCpDMGvV2BGHeYERUEnRQAwe3N8SzbUtfsmvsqQLuvuJ",
    "/ip4/104.131.131.82/udp/4001/quic/p2p/QmaCpDMGvV2BGHeYERUEnRQAwe3N8SzbUtfsmvsqQLuvuJ"
  ],
  "DNS": {
    "Resolvers": {}
  },
  "Datastore": {
    "BloomFilterSize": 0,
    "GCPeriod": "1h",
    "HashOnRead": false,
    "Spec": {
      "mounts": [
        {
          "child": {
            "path": "blocks",
            "shardFunc": "/repo/flatfs/shard/v1/next-to-last/2",
            "sync": true,
            "type": "flatfs"
          },
          "mountpoint": "/blocks",
          "prefix": "flatfs.datastore",
          "type": "measure"
        },
        {
          "child": {
            "compression": "none",
            "path": "datastore",
            "type": "levelds"
          },
          "mountpoint": "/",
          "prefix": "leveldb.datastore",
          "type": "measure"
        }
      ],
      "type": "mount"
    },
    "StorageGCWatermark": 90,
    "StorageMax": "10GB"
  },
  "Discovery": {
    "MDNS": {
      "Enabled": true
    }
  },
  "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": "",
    "Writable": false
  },
  "Identity": {
    "PeerID": "12D3KooWQF6Q3i1QkziJQ9mkNNcyFD8GPQz6R6oEvT75wgsVXm4v"
  },
  "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
  },
  "Swarm": {
    "AddrFilters": null,
    "ConnMgr": {},
    "DisableBandwidthMetrics": false,
    "DisableNatPortMap": false,
    "RelayClient": {},
    "RelayService": {},
    "ResourceMgr": {},
    "Transports": {
      "Multiplexers": {},
      "Network": {},
      "Security": {}
    }
  }
}

Description

Ran my kubo daemon with GOLOG_LOG_LEVEL="warn,webtransport=debug,reuseport-transport=warn,net/identify=error" cmd/ipfs/ipfs daemon 2>&1 | tee kubo-log.txt because I was debugging other stuff. I left it running since friday, and my laptop slept over the weekend. When opening it back up, I have a spamming of these errors:

2023-03-25T04:06:08.652-0700    WARN    nat nat/nat.go:179  failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.1.1:36171/ctl/IPConn": dial tcp 192.168.1.1:36171: connect: connection refused

full log at https://bafybeiaxuasctnq3sgwwgtgdk6q2rlvuwe4s37bfzin7z7cnt6byesdpvq.ipfs.w3s.link/bafybeig6sodjrftg5eetjzlcvm7nx4qcwgwbe72n4ps6nuebdemj5aa62u

Repro?

Not yet.. i'll add to this if it occurs after a long sleep again

Killing daemon CTRL+C and restarting it does not show me these errors.

Other Details

My public IP (dynamic IP from ISP) is different than what it was on Friday

Clear bugs (to me)

  1. Spamming of port mapping attempts even though it has failed hundreds of times. There are 4-6 requests PER MINUTE. This is too much. fix this. exponential backoff and circuit breaker required (unless this log is outside of those functions.. but I doubt it.. if it is, add more log info)
  2. It doesn't seem like the necessary logic to successfully establish port mapping (as is done during daemon start) is done after these failures.. which SHOULD be done. If I can kill kubo daemon and start again immediately without seeing these errors again, you should be able to handle this case without me.

Related issues

Couldn't find any in this repo, but I found the following in lotus, which I don't think actually addresses the root issue:

Potentially related issues

SgtPooki commented 1 year ago

Note that I related #3320 because this type of behavior could easily kill routers... but it did not kill mine.

How many other calls are we sending without exponential backoff and circuit breaking on failures?

Do we not have exponential backoff and/or circuit breaking? Why is nat/nat.go:179 called SO many times per minute? It looks like we have some throttling, https://github.com/ipfs/kubo/blob/88d431c8129aeef2ea5076336412cb54161342ce/core/node/libp2p/nat.go#L20, but that appears to be on an individual basis and that there are multiple consumers/deps trying to use AutoNatService.