miniupnp icon indicating copy to clipboard operation
miniupnp copied to clipboard

Published 20 hours ago • verified publisher icon miniupnp

minissdpd: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp5s0): Address already in use

Open bigon opened this issue 5 years ago • 14 comments

Hello,

From time to time, minissdpd complains that

minissdpd: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp5s0): Address already in use

I investigated that a bit and it seems that the linux kernel is periodically sending a RTM_NEWADDR netlink message even if there are no changes to the addresses of the interface (ip monitor shows that as well).

I was wondering, why is it relevant for ipv6 as the membership is done on the index of the interface and not the addresses, shouldn't these messages be ignored then?

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=921914

bigon avatar Jan 06 '20 01:01 bigon

I think when there is a new interface coming up, minissdpd receives first RTM_NEWLINK and then RTM_NEWADDR.

but I believe it has to wait for RTM_NEWADDR to subscribe to Multicast membership.

miniupnp avatar Apr 09 '20 22:04 miniupnp

@bigon I do not reproduce the issue on a 3.14.32 kernel. Can you provide log of ip monitor ?

miniupnp avatar Apr 12 '20 18:04 miniupnp

@bigon I do not reproduce the issue on a 3.14.32 kernel. Can you provide log of ip monitor ?

@miniupnp I only have machines with debian unstable and kernel 5.x

Would that still be useful?

bigon avatar Apr 17 '20 12:04 bigon

well we need logs of what happens on your machine...

miniupnp avatar Apr 17 '20 13:04 miniupnp

minissdpd shows:

avr 18 19:38:00 fornost minissdpd[1226]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp5s0): Address already in use
avr 18 19:38:00 fornost minissdpd[1226]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp5s0): Address already in use
avr 18 19:38:00 fornost minissdpd[1226]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp5s0): Address already in use
avr 18 19:38:00 fornost minissdpd[1226]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp5s0): Address already in use

And ip monitor shows at the same moment:

2: enp5s0    inet6 fe80::xxxx:xxxx:xxxx:xxxx/64 scope link noprefixroute 
       valid_lft forever preferred_lft forever
2: enp5s0    inet6 2a02:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx/64 scope global dynamic noprefixroute 
       valid_lft 71149sec preferred_lft 56749sec
2: enp5s0    inet6 fde3:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx/64 scope global noprefixroute 
       valid_lft forever preferred_lft forever
2: enp5s0    inet6 fd00:xxxx:1:xxxx:xxxx:xxxx:xxxx/64 scope global dynamic noprefixroute 
       valid_lft 7200sec preferred_lft 7200sec
192.168.1.1 dev enp5s0 lladdr <MAC> PROBE
192.168.1.1 dev enp5s0 lladdr <MAC> REACHABLE
fe80::xxxx:xxxx:xxxx:xxxx dev enp5s0 lladdr <MAC> router STALE
192.168.1.6 dev enp5s0 lladdr <MAC> STALE

bigon avatar Apr 18 '20 17:04 bigon

and the same messages are repeated ? at which frequency ?

miniupnp avatar Apr 19 '20 16:04 miniupnp

I'm getting this every 2 or 3 minutes on my machine here

The IPv6 router is refreshing the dynamically assigned address, I guess?

bigon avatar Apr 19 '20 22:04 bigon

This reported issue also happens on my router (Debian Bullseye (rolling testing release), which is almost the same as the original reporter. The version of minissdpd is git version obtained 00:10 (midnight) May 31 UTC. The relevant log is attached below. It is repeated every 10 minutes.


(no log at 15:29:19 )
May 31 15:29:19 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:29:19 router1 minissdpd[9895]: minissdpd[9895]:  rta_len=20 rta_type=1 '2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f'
May 31 15:29:19 router1 minissdpd[9895]: minissdpd[9895]:  rta_len=20 rta_type=6 'valid=14400 preferred=12600'
May 31 15:29:19 router1 minissdpd[9895]: minissdpd[9895]:  rta_len=8 rta_type=8 '*unknown*'
May 31 15:29:19 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:29:19 router1 minissdpd[9895]: minissdpd[9895]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp0s25): Address already in use
May 31 15:29:19 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:29:19 router1 minissdpd[9895]:  rta_len=20 rta_type=1 '2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f'
May 31 15:29:19 router1 minissdpd[9895]:  rta_len=20 rta_type=6 'valid=14400 preferred=12600'
May 31 15:29:19 router1 minissdpd[9895]:  rta_len=8 rta_type=8 '*unknown*'
May 31 15:29:19 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:29:19 router1 minissdpd[9895]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp0s25): Address already in use


May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: SSDP request: 'NOTIFY' (2) ssdp:alive nt=urn:schemas-upnp-org:service:ConnectionManager:1
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: device updated : uuid:43b0fa8e-5efa-8eb9-23f3-8e095eb957ee::urn:schemas-upnp-org:service:ConnectionManager:1
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: ** i=0 deltadev=0 **
May 31 15:41:11 router1 minissdpd[9895]: SSDP request: 'NOTIFY' (2) ssdp:alive nt=urn:schemas-upnp-org:service:ConnectionManager:1
May 31 15:41:11 router1 minissdpd[9895]: device updated : uuid:43b0fa8e-5efa-8eb9-23f3-8e095eb957ee::urn:schemas-upnp-org:service:ConnectionManager:1
May 31 15:41:11 router1 minissdpd[9895]: ** i=0 deltadev=0 **
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: SSDP request: 'NOTIFY' (2) ssdp:alive nt=urn:schemas-upnp-org:service:AVTransport:1
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: device updated : uuid:43b0fa8e-5efa-8eb9-23f3-8e095eb957ee::urn:schemas-upnp-org:service:AVTransport:1
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: ** i=0 deltadev=0 **
May 31 15:41:11 router1 minissdpd[9895]: SSDP request: 'NOTIFY' (2) ssdp:alive nt=urn:schemas-upnp-org:service:AVTransport:1
May 31 15:41:11 router1 minissdpd[9895]: device updated : uuid:43b0fa8e-5efa-8eb9-23f3-8e095eb957ee::urn:schemas-upnp-org:service:AVTransport:1
May 31 15:41:11 router1 minissdpd[9895]: ** i=0 deltadev=0 **
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]:  rta_len=20 rta_type=1 '2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f'
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]:  rta_len=20 rta_type=6 'valid=14400 preferred=12600'
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]:  rta_len=8 rta_type=8 '*unknown*'
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp0s25): Address already in use
May 31 15:41:11 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:41:11 router1 minissdpd[9895]:  rta_len=20 rta_type=1 '2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f'
May 31 15:41:11 router1 minissdpd[9895]:  rta_len=20 rta_type=6 'valid=14400 preferred=12600'
May 31 15:41:11 router1 minissdpd[9895]:  rta_len=8 rta_type=8 '*unknown*'
May 31 15:41:11 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:41:11 router1 minissdpd[9895]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp0s25): Address already in use


(no log at 15:50:25)
May 31 15:50:25 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:50:25 router1 minissdpd[9895]: minissdpd[9895]:  rta_len=20 rta_type=1 '2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f'
May 31 15:50:25 router1 minissdpd[9895]: minissdpd[9895]:  rta_len=20 rta_type=6 'valid=14400 preferred=12600'
May 31 15:50:25 router1 minissdpd[9895]: minissdpd[9895]:  rta_len=8 rta_type=8 '*unknown*'
May 31 15:50:25 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:50:25 router1 minissdpd[9895]: minissdpd[9895]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp0s25): Address already in use
May 31 15:50:25 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:50:25 router1 minissdpd[9895]:  rta_len=20 rta_type=1 '2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f'
May 31 15:50:25 router1 minissdpd[9895]:  rta_len=20 rta_type=6 'valid=14400 preferred=12600'
May 31 15:50:25 router1 minissdpd[9895]:  rta_len=8 rta_type=8 '*unknown*'
May 31 15:50:25 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:50:25 router1 minissdpd[9895]: setsockopt(udp, IPV6_JOIN_GROUP)(FF02::C, enp0s25): Address already in use

emojifreak avatar May 31 '20 07:05 emojifreak

journalctl -g RTM_NEWADDR shows the following. It is interesting that RTM_NEWADDR says the always same address 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f, i.e., there is no new assigned IPv6 address. But minissdpd somehow think it is a new address. This is strange. A workaround could be to check whether the "new" address is really different from an already assigned address...

-- Reboot --
May 31 12:26:15 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 12:26:15 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 12:26:15 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 12:26:15 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 12:54:54 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 12:54:54 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 12:54:54 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 12:54:54 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 13:16:35 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 13:16:35 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 13:16:35 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 13:16:35 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 13:42:52 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 13:42:52 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 13:42:52 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 13:42:52 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 14:09:17 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 14:09:17 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 14:09:17 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 14:09:17 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 14:35:15 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 14:35:15 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 14:35:15 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 14:35:15 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 14:57:58 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 14:57:58 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 14:57:58 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 14:57:58 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:23:20 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:23:20 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:23:20 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:23:20 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:29:19 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:29:19 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:29:19 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:29:19 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:41:11 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:41:11 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:41:11 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:50:25 router1 minissdpd[9895]: minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:50:25 router1 minissdpd[9895]: minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64
May 31 15:50:25 router1 minissdpd[9895]: ProcessInterfaceWatchNotify RTM_NEWADDR index=2 fam=10 prefixlen=64 flags=0 scope=0
May 31 15:50:25 router1 minissdpd[9895]: RTM_NEWADDR: 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64

emojifreak avatar May 31 '20 07:05 emojifreak

It is common for an interface to have multiple IPv6 address. My uninformed guess is that minissdpd compares "newly assigned address", which is not really NEW at all, with one of already assigned addresses that is different from the "new" address. Then minissdpd thinks that the "new" address is really new. An interface in my router has three IPv6 addresses ad follows:

# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: enp0s25: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether 00:1b:d3:88:9b:8f brd ff:ff:ff:ff:ff:ff
    inet 192.168.1.2/24 brd 192.168.1.255 scope global enp0s25
       valid_lft forever preferred_lft forever
    inet6 2400:4050:2ba1:ac00:21b:d3ff:fe88:9b8f/64 scope global dynamic mngtmpaddr noprefixroute 
       valid_lft 14316sec preferred_lft 12516sec
    inet6 2400:4050:2ba1:ac00:99:f0ae:8600:2c00/64 scope global 
       valid_lft forever preferred_lft forever
    inet6 fe80::21b:d3ff:fe88:9b8f/64 scope link 
       valid_lft forever preferred_lft forever

emojifreak avatar May 31 '20 07:05 emojifreak

minissdpd compares nothing. It receives a RTM_NEWADDR messages and process it. I just don't know why your kernel is sending spurious RTM_NEWADDR messages.

https://man7.org/linux/man-pages/man7/rtnetlink.7.html

miniupnp avatar Jun 01 '20 22:06 miniupnp

It receives a RTM_NEWADDR messages and process it. I just don't know why your kernel is sending spurious RTM_NEWADDR messages.

Thank you for your comment. I have no idea, neither. I will investigate it later, and if I can figure it well, I will file a bug report against the Debian kernel package (or return here). Another possibility is a bug in a router giving IPv6 addresses...

emojifreak avatar Jun 02 '20 00:06 emojifreak

Like I said in my initial report, the multicast membership with IPv6 is made using the interface, not the local address. So even if the IPv6 address on an interface is changed, that should change nothing for the multicast membership. Shouldn't these messages just be ignored then?

bigon avatar Jun 02 '20 08:06 bigon

@bigon does the problem still happens with newer kernels ?

If that is still an issue, we could try either to find a way to avoid/detect the spurious RTM_NEWADDR messages, or don't log this "error"

We could even ignore the error only if the linux kernel version is a specific range.

miniupnp avatar Oct 15 '22 11:10 miniupnp