nat: stuck in error loop after router restart

[lidel]

Problem

Restarting LAN router breaks uPnP?

Repro

I have a long running node (Kubo 0.34.0-rc1) that had port forwarding set up via nat module.

Once the router in my network got restarted due to unrelated DHCP changes, the go-libp2p in Kubo started logging below error in loop (every 20 seconds):

2025-03-07T16:25:50.397Z	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.50.1:44902/ctl/IPConn": dial tcp 192.168.50.1:44902: connect: connection refused
2025-03-07T16:25:50.421Z	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.50.1:44902/ctl/IPConn": dial tcp 192.168.50.1:44902: connect: connection refused
2025-03-07T16:26:10.443Z	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.50.1:44902/ctl/IPConn": dial tcp 192.168.50.1:44902: connect: connection refused
2025-03-07T16:26:10.466Z	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.50.1:44902/ctl/IPConn": dial tcp 192.168.50.1:44902: connect: connection refused
2025-03-07T16:26:30.496Z	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.50.1:44902/ctl/IPConn": dial tcp 192.168.50.1:44902: connect: connection refused
2025-03-07T16:26:30.516Z	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.50.1:44902/ctl/IPConn": dial tcp 192.168.50.1:44902: connect: connection refused
2025-03-07T16:26:50.533Z	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.50.1:44902/ctl/IPConn": dial tcp 192.168.50.1:44902: connect: connection refused
2025-03-07T16:26:50.552Z	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.50.1:44902/ctl/IPConn": dial tcp 192.168.50.1:44902: connect: connection refused

This looks like a gap in our logic, perhaps we should detect when the same :port/ctl/IPConn fails multiple times (indicating the router restarted) and trigger re-discovery to self-heal this?

Version info

• kubo 0.34.0-rc1
  • github.com/libp2p/go-libp2p v0.41.0
    • github.com/huin/goupnp v1.3.0
• Router implementation uses MiniUPnP 2.2.0

[2color]

This might be related to #3154 which was released in github.com/libp2p/go-libp2p v0.41.0, though very unlikely given the scope of changes in that PR.

Is this a new problem you noticed? It might also just be that we now bubble up and log the errors better (thanks to #3154).

[lidel]

I suspect this has always been a problem – router restarts are very rare, so perhaps nobody noticed+reported this before?

[MarcoPolo]

Unlikely this was introduced in #3154.

My guess for a fix would be to track persistent connection refused errors and resync the nat mappings if it crosses some threshold. i.e. if we fail to connect 3 times in a row, trigger a nat manager sync.

[sukunrt]

Just so I understand what happened here:
Did your router's UPnP port or IP change after restart? It looks like the upnp port is 0(192.168.50.1:44902).

[lidel]

Ok, was able to reproduce this every time in Kubo – see ipfs/kubo#9759 (comment) and also with pure go-libp2p (see below)

Important

Losing forwarded port and not being able to recover from that state is a problem, we likely have long running Kubo nodes that people use for self-hosting data in consumer networks. Consumer routers sometimes restart or even crash. Once that occurs, such nodes are no longer publicly diallable and at best depend on relays

---

@sukunrt looks like there is this HTTP port change + also not persisting mappings across restarts?

My off-the-shelf Asus router uses miniupnpd and by default the HTTP port (used for descriptions and SOAP) changes across restarts:

Jan  1 01:00:39 miniupnpd[1921]: HTTP listening on port 48369
Jan  1 01:00:39 miniupnpd[1921]: Listening for NAT-PMP/PCP traffic on port 5351
[..] (router restart)
Jan  1 01:00:46 miniupnpd[2192]: HTTP listening on port 58533
Jan  1 01:00:46 miniupnpd[2192]: Listening for NAT-PMP/PCP traffic on port 5351

This is not specific to my router, this is the default in the software that is likely used by many many consumer grade routers (miniupnpd.conf#L66-L67)

How to reproduce

You can reproduce this by running go run . in go-libp2p/examples/autotls, waiting for nat to set up forwarding, and then restarting the router. It won't be able to recover.

Restarted my router to read miniupnpd ports (ignore Jan 1, it updates time after miniupnpd starts):

Jan  1 01:00:46 miniupnpd[2192]: HTTP listening on port 58533
Jan  1 01:00:46 miniupnpd[2192]: Listening for NAT-PMP/PCP traffic on port 5351

Start nat and set up initial port forwarding:

2025-05-09T16:31:45.854+0200	DEBUG	nat	nat/nat.go:229	Attempting port map: tcp/5500
2025-05-09T16:31:45.859+0200	DEBUG	nat	nat/nat.go:253	NAT Mapping: 42535 --> 5500 (tcp)

Restart router (note HTTP port changed from 58533 to 35740):

Jan  1 01:00:39 miniupnpd[1948]: HTTP listening on port 35740
Jan  1 01:00:39 miniupnpd[1948]: Listening for NAT-PMP/PCP traffic on port 5351

go-libp2p starts logging failures about the old 58533 port, never recovers, never learns the new one:

2025-05-09T16:35:45.976+0200	DEBUG	nat	nat/nat.go:229	Attempting port map: tcp/5500
2025-05-09T16:36:45.995+0200	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.1.1:58533/ctl/IPConn": dial tcp 192.168.1.1:58533: connect: connection refused
2025-05-09T16:37:05.996+0200	DEBUG	nat	nat/nat.go:229	Attempting port map: tcp/5500
2025-05-09T16:37:06.056+0200	WARN	nat	nat/nat.go:244	failed to establish port mapping: goupnp: error performing SOAP HTTP request: Post "http://192.168.1.1:58533/ctl/IPConn": dial tcp 192.168.1.1:58533: connect: connection refused