search

openwrt / packages

Community maintained packages for OpenWrt. Documentation for submitting pull requests is in CONTRIBUTING.md
GNU General Public License v2.0
3.98k stars 3.47k forks source link

miniupnpd: logspam(?) - error flood #17258

Open systemcrash opened 2 years ago

systemcrash commented 2 years ago

Issue template (remove lines from top till here)

Maintainer: - Environment:

Hostname asdf
Model TP-Link Archer C7 v2
Architecture Qualcomm Atheros QCA9558 ver 1 rev 0
Firmware Version OpenWrt 21.02.1 r16325-88151b8303 / LuCI openwrt-21.02 branch git-21.295.67054-13df80d
Kernel Version 5.4.154

For the last ~30 days it has been OK. Only recently started. Not harmful, but it's hard to see anything else in the logs for this noise. If No such device is encountered, surely the leases can be pruned/trimmed? Just thinking out loud. Also don't understand the Permission denied errors... :shrug:

Description: logs flood every 30 seconds with:


Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=7, 192.168.19.1): No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: sendto(udp_notify=8, [fd51:1c2a:8909::1]): Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=473, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=473, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=489, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=485, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=473, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=471, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=418, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=457, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=418, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=477, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=418, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=481, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=409, dest=[ff0e::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=473, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=473, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=489, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=485, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=473, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=471, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=418, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=457, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=418, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=477, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=418, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=481, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=409, dest=[ff05::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=473, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=473, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=489, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=485, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=473, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=471, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=418, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=457, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=418, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=477, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=418, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=481, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=8, len=409, dest=[ff02::c]:1900): sendto: Permission denied
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=472, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=472, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=488, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=484, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=472, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=470, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=417, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=456, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=417, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=476, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=417, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=480, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto(sock=7, len=408, dest=239.255.255.250:1900): sendto: No such device
Thu Dec  2 17:08:42 2021 daemon.err miniupnpd[6079]: try_sendto failed to send 52 packets
# ps | grep miniupnp
 6079 root      1444 S    /usr/sbin/miniupnpd -f /var/etc/miniupnpd.conf
18891 root      1252 S    grep miniupnp
root@asdf:~# cat /var/etc/miniupnpd.conf
ext_ifname=eth0.2
ext_ifname6=6in4-HENET
listening_ip=br-lan
enable_natpmp=yes
enable_upnp=yes
secure_mode=yes
system_uptime=yes
force_igd_desc_v1=yes
ext_perform_stun=no
ipv6_disable=no
bitrate_down=8388608
bitrate_up=4194304
lease_file=/var/run/miniupnpd.leases
port=5000
uuid=fbc461fc-5453-45ce-8121-e628cb54a256
allow 1024-65535 0.0.0.0/0 1024-65535 #Allow high ports
deny 0-65535 0.0.0.0/0 0-65535 #Default deny
# cat /etc/config/upnpd

config upnpd 'config'
    option download '1024'
    option upload '512'
    option internal_iface 'lan'
    option port '5000'
    option upnp_lease_file '/var/run/miniupnpd.leases'
    option igdv1 '1'
    option enabled '1'
    option uuid 'fbc461fc-5453-45ce-8121-e628cb54a256'

config perm_rule
    option action 'allow'
    option ext_ports '1024-65535'
    option int_addr '0.0.0.0/0'
    option int_ports '1024-65535'
    option comment 'Allow high ports'

config perm_rule
    option action 'deny'
    option ext_ports '0-65535'
    option int_addr '0.0.0.0/0'
    option int_ports '0-65535'
    option comment 'Default deny'

/var/run/miniupnpd.leases does not exist. the leases file doesn't exist anywhere.

IPv6 ULA-Prefix fd51:1c2a:8909::/48

Trimmed route6 table.

# route -A inet6
Kernel IPv6 routing table
Destination                                 Next Hop                                Flags Metric Ref    Use Iface
...
fd51:1c2a:8909::/64                         ::                                      U     1024   2        0 br-lan
fd51:1c2a:8909::/48                         ::                                      !n    2147483647 2        0 lo
...
fd51:1c2a:8909::/128                        ::                                      Un    0      3        0 br-lan
fd51:1c2a:8909::1/128                       ::                                      Un    0      4        0 br-lan
...
ff00::/8                                    ::                                      U     256    4        0 eth1
ff00::/8                                    ::                                      U     256    2        0 br-lan
ff00::/8                                    ::                                      U     256    2        0 eth0.2
ff00::/8                                    ::                                      U     256    1        0 eth0
ff00::/8                                    ::                                      U     256    1        0 wg0
ff00::/8                                    ::                                      U     256    1        0 6in4-HENET
ff00::/8                                    ::                                      U     256    1        0 wg1
ff00::/8                                    ::                                      U     256    1        0 wlan0
ff00::/8                                    ::                                      U     256    1        0 wlan1
...
professor-jonny commented 2 years ago

I get the same SSDP discovery constant logs but im not sure if my issue is 100% the same as yours I get no such device error on my interface instead of permission errors.

It looks like for me the multicast ssdp discovery events are not being sent on my wireless only bridge interface on my router but they are on my mixed wireless/ wired bridge on another interface.

I'm wondering if the interface goes down and comes back up if some sort of hotplug event needs to run to get it all working again?

239.255.255.250:1900 is an ssdp event and it should not error as it is used as the broadcast address to announce to other devices on the network is it not?.

Fri Dec 24 23:19:30 2021 daemon.err miniupnpd[5745]: sendto(udp_notify=6, 192.168.2.1): No such device Fri Dec 24 23:19:30 2021 daemon.err miniupnpd[5745]: try_sendto(sock=6, len=465, dest=239.255.255.250:1900): sendto: No such device

systemcrash commented 2 years ago

I get a number of things in the logs from miniupnpd currently:

Fri Dec 24 13:12:10 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:10 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:13 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:13 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:13 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:13 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:14 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:14 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:14 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:14 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:14 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:14 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 33491 tcp->192.168.1.2:22000 'NAT-PMP 33491 tcp'
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 25218 tcp->192.168.1.2:22000 'NAT-PMP 25218 tcp'
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 16299 tcp->192.168.1.2:22000 'NAT-PMP 16299 tcp'
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 61737 tcp->192.168.1.2:22000 'NAT-PMP 61737 tcp'
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 49074 tcp->192.168.1.2:22000 'NAT-PMP 49074 tcp'
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 32844 tcp->192.168.1.2:22000 'NAT-PMP 32844 tcp'
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 64007 tcp->192.168.1.2:22000 'NAT-PMP 64007 tcp'
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 58207 tcp->192.168.1.2:22000 'NAT-PMP 58207 tcp'
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 35266 tcp->192.168.1.2:22000 'NAT-PMP 35266 tcp'
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: addnatrule() : chain MINIUPNPD not found
Fri Dec 24 13:12:15 2021 daemon.err miniupnpd[6138]: Failed to add NAT-PMP 23413 tcp->192.168.1.2:22000 'NAT-PMP 23413 tcp'

It seems like it needs to learn how to correctly add a chain to the fw. So this is a concrete problem for which a fix is theoretically possible. Perhaps the module installation should take care of adding a MINIUPNPD chain to the fw, if there isn't a better way of handling this.

What I find strange is that this does not immediately appear in the logs - it only seems to arise after the system has been up for a week or two already.

systemcrash commented 2 years ago

I'm wondering if the interface goes down and comes back up if some sort of hotplug event needs to run to get it all working again?

usually a restart makes the problem go away for a while

239.255.255.250:1900 is an ssdp event and it should not error as it is used as the broadcast address to announce to other devices on the network is it not?.

you'd be surprised...

Fri Dec 24 23:19:30 2021 daemon.err miniupnpd[5745]: sendto(udp_notify=6, 192.168.2.1): No such device Fri Dec 24 23:19:30 2021 daemon.err miniupnpd[5745]: try_sendto(sock=6, len=465, dest=239.255.255.250:1900): sendto: No such device

This looks similar: sendto: problems mean some resource that was there earlier disappears - whether hardware, config, memory, etc. Not looked at any miniupnpd code.

professor-jonny commented 2 years ago

In my case I have a time controlled firewall and upnp is blocked on the interface when the rule starts and I start getting these errors. It seems miniupnpd needs to be aware of changes made to the firewall and hotplug events of interfaces ?

tiagogaspar8 commented 2 years ago

Hi @systemcrash, does this still happen with the latest miniupnpd versions? I remember I faced this with an older version but the issue was solved in the meantime

mingww64 commented 1 year ago

I have this issue lately, is there any progress?

systemcrash commented 1 year ago

Hi @systemcrash, does this still happen with the latest miniupnpd versions? I remember I faced this with an older version but the issue was solved in the meantime

Current build:

Powered by LuCI openwrt-22.03 branch (git-22.288.45147-96ec0cd) / OpenWrt 22.03.2 r19803-9a599fee93

Its behaviour seems to have improved, but upon inspection of my kernel logs, it shows this:

[764859.941063] kthreadd invoked oom-killer: gfp_mask=0x400dc0(GFP_KERNEL_ACCOUNT|__GFP_ZERO), order=1, oom_score_adj=0
[764859.952113] CPU: 0 PID: 2 Comm: kthreadd Not tainted 5.10.146 #0
[764859.958298] Stack : 00000840 800bf418 80750000 80651520 00000000 00000000 00000000 00000000
[764859.966924]         00000000 00000000 00000000 00000000 00000000 00000001 80c39c10 566f43ea
[764859.976095]         80c39ca8 00000000 00000000 80c39ab8 00000038 80326544 00000000 ffffffea
[764859.984729]         00000132 80c39ac4 00000132 806e1a88 80c39bf0 80629d88 00000000 00000000
[764859.993321]         00000800 00000000 00400dc0 00000840 00000000 8038c494 00000000 808a0000
[764860.002255]         ...
[764860.004848] Call Trace:
[764860.004859] [<800bf418>] 0x800bf418
[764860.011087] [<80326544>] 0x80326544
[764860.014709] [<8038c494>] 0x8038c494
[764860.018333] [<8006697c>] 0x8006697c
[764860.021973] [<80066984>] 0x80066984
[764860.025593] [<801523d8>] 0x801523d8
[764860.029220] [<80152c64>] 0x80152c64
[764860.032857] [<80153610>] 0x80153610
[764860.036480] [<801963f0>] 0x801963f0
[764860.040116] [<800a0508>] 0x800a0508
[764860.043743] [<80082d38>] 0x80082d38
[764860.047364] [<800b0fec>] 0x800b0fec
[764860.051006] [<80084100>] 0x80084100
[764860.054633] [<800b2bd8>] 0x800b2bd8
[764860.058259] [<800a2cf4>] 0x800a2cf4
[764860.061896] [<8008451c>] 0x8008451c
[764860.068148] [<800a2cf4>] 0x800a2cf4
[764860.072284] [<800a2cf4>] 0x800a2cf4
[764860.075963] [<800a4848>] 0x800a4848
[764860.079590] [<800a4770>] 0x800a4770
[764860.083256] [<800a4770>] 0x800a4770
[764860.086876] [<80062178>] 0x80062178
[764860.090518] 
[764860.092119] Mem-Info:
[764860.094519] active_anon:310 inactive_anon:1731 isolated_anon:0
[764860.094519]  active_file:131 inactive_file:222 isolated_file:0
[764860.094519]  unevictable:0 dirty:0 writeback:0
[764860.094519]  slab_reclaimable:291 slab_unreclaimable:12391
[764860.094519]  mapped:108 shmem:300 pagetables:122 bounce:0
[764860.094519]  free:3712 free_pcp:0 free_cma:0
[764860.127249] Node 0 active_anon:1240kB inactive_anon:6924kB active_file:524kB inactive_file:888kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:432kB dirty:0kB writeback:0kB shmem:1200kB writeback_tmp:0kB kernel_stack:472kB all_unreclaimable? no
[764860.150659] Normal free:14816kB min:16384kB low:20480kB high:24576kB reserved_highatomic:0KB active_anon:1240kB inactive_anon:6924kB active_file:524kB inactive_file:888kB unevictable:0kB writepending:0kB present:131072kB managed:122316kB mlocked:0kB pagetables:488kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[764860.181680] lowmem_reserve[]: 0 0
[764860.185155] Normal: 208*4kB (UME) 138*8kB (UME) 47*16kB (UME) 19*32kB (UME) 10*64kB (UME) 25*128kB (UME) 10*256kB (UE) 6*512kB (UME) 2*1024kB (U) 0*2048kB 0*4096kB = 14816kB
[764860.201046] 653 total pagecache pages
[764860.206276] 0 pages in swap cache
[764860.209734] Swap cache stats: add 0, delete 0, find 0/0
[764860.215161] Free swap  = 0kB
[764860.218170] Total swap = 0kB
[764860.221188] 32768 pages RAM
[764860.224110] 0 pages HighMem/MovableOnly
[764860.228087] 2189 pages reserved
[764860.231364] Tasks state (memory values in pages):
[764860.236219] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
[764860.245066] [    601]    81   601      364       33    16384        0             0 ubusd
[764860.253457] [    602]     0   602      249       10    20480        0             0 askfirst
[764860.262120] [    637]     0   637      277       14    20480        0             0 urngd
[764860.270516] [   1226]   514  1226      335       37    20480        0             0 logd
[764860.281098] [   1280]     0  1280      574       98    16384        0             0 rpcd
[764860.289396] [   1696]     0  1696      664       25    16384        0             0 hostapd
[764860.298002] [   1697]     0  1697      664       25    16384        0             0 wpa_supplicant
[764860.308565] [   1700]   101  1700     1238       83    20480        0             0 hostapd
[764860.317179] [   1720]   101  1720     1220       31    20480        0             0 wpa_supplicant
[764860.326370] [   1763]     0  1763      466       69    16384        0             0 netifd
[764860.334852] [   1821]     0  1821      388       32    16384        0             0 odhcpd
[764860.343331] [   1884]     0  1884      331       14    16384        0             0 crond
[764860.351719] [   1959]     0  1959      976      329    20480        0             0 uhttpd
[764860.360203] [   2220]     0  2220      327       10    16384        0             0 udhcpc
[764860.368675] [   2225]     0  2225      281       15    12288        0             0 odhcp6c
[764860.377241] [   2502]     0  2502      302       13    20480        0             0 dropbear
[764860.387906] [   3353]     0  3353      664       26    20480        0             0 ntpd
[764860.396256] [   3387]   123  3387      327       12    20480        0             0 ntpd
[764860.404566] [   5709]     0  5709      400       84    20480        0             0 dynamic_dns_upd
[764860.414358] [   6501] 65534  6501      790      173    28672        0             0 https-dns-proxy
[764860.423664] [   6502] 65534  6502      809      176    20480        0             0 https-dns-proxy
[764860.432943] [   6806]     0  6806      777      405    24576        0             0 miniupnpd
[764860.441693] [  20376]     0 20376      664       26    16384        0             0 dnsmasq
[764860.452301] [  20379]   453 20379      382       72    20480        0             0 dnsmasq
[764860.463293] [  19379]     0 19379      329       13    20480        0             0 sleep
[764860.472138] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),global_oom,task_memcg=/,task=miniupnpd,pid=6806,uid=0
[764860.483375] Out of memory: Killed process 6806 (miniupnpd) total-vm:3108kB, anon-rss:1616kB, file-rss:4kB, shmem-rss:0kB, UID:0 pgtables:24kB oom_score_adj:0

I suspect this is the result of LAN clients opening many forwards. Not certain whether I should flag this as a bug with openwrt.

systemcrash commented 9 months ago

Still get this on 23.05.2. I suspect also 24 when it comes.

The root of this problem could be a LAN client opens port(forward)s via UPNP, and those ports then become invalid/deallocated, but somehow miniupnpd didn't get the memo...?

The error messages appear non-sensical, but instead of the original permission denied, they're now:

Wed Jan 24 21:49:30 2024 daemon.err miniupnpd[11218]: sendto(udp_notify=8, 192.168.19.1): No such device
(repeats 12 times)
Wed Jan 24 21:49:30 2024 daemon.err miniupnpd[11218]: sendto(udp_notify=9, [fd51:1c2a:8909::1]): Network unreachable
(repeats 40 times)
Wed Jan 24 21:49:30 2024 daemon.err miniupnpd[11218]: try_sendto(sock=9, len=467, dest=[ff0e::c]:1900): sendto: Network unreachable
(repeats 13 times with varying len=x )
Wed Jan 24 21:49:30 2024 daemon.err miniupnpd[11218]: try_sendto(sock=9, len=467, dest=[ff05::c]:1900): sendto: Network unreachable
(repeats 13 times with varying len=x )
Wed Jan 24 21:49:30 2024 daemon.err miniupnpd[11218]: try_sendto(sock=9, len=467, dest=[ff02::c]:1900): sendto: Network unreachable
(repeats 13 times with varying len=x )
Wed Jan 24 21:49:30 2024 daemon.err miniupnpd[11218]: try_sendto(sock=8, len=466, dest=239.255.255.250:1900): sendto: No such device
(repeats 12 times with varying len=x )
Wed Jan 24 21:49:30 2024 daemon.err miniupnpd[11218]: try_sendto failed to send 52 packets

miniupnpd could do well to recover better from these scenarios. 🤷