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

[SgtPooki]

Checklist

• This is a bug report, not a question. Ask questions on discuss.ipfs.io.
• I have searched on the issue tracker for my bug.
• I am running the latest kubo version or have an issue updating.

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:

• failed to establish port mapping: goupnp: SOAP request got HTTP 500 Internal Server Error filecoin-project/lotus#2571
• failed to establish port mapping: goupnp: SOAP request got HTTP 500 Internal Server Error filecoin-project/lotus#4083
• config for disabling NAT port mapping filecoin-project/lotus#7204

Potentially related issues

• Writeup of router kill issue #3320

[SgtPooki]

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,

kubo/core/node/libp2p/nat.go

Line 20 in 88d431c

throttle.Interval.WithDefault(time.Minute),

, but that appears to be on an individual basis and that there are multiple consumers/deps trying to use AutoNatService.