On Thu, Oct 24 2019 16:09:41 -0400, kwesterb...@gmail.com wrote: > >>> # route monitor >/tmp/route-monitor.good & > >>> # dhclient vio0 > >>> # ping 1.1.1.1 > >> > >> Can you add a "ifconfig vio0" at this point, > >>> ^C > >>> # ifconfig vio0 -soii > >>> # ping 1.1.1.1 > >> > >> and here.
> > I can of course repeat any of these tests on a -CURRENT system vs. a > > -CURRENT system that has the commit that introduced the problem > > reverted, if you like. > > Yes, please. So once more, with feeling. These are the bsd.rd's under test: bad: cc77704b1667b9e88ff797de7c9baefae04bf275 aka if_vio.c r1.14 good: same as previous, but with the following diff. The revert of dhclient.c r1.634 did not apply cleanly because of more recent changes to the code (namely r1.635), so I've manually made what I think is the inverse change here, to not restart if the link state did not change. This diff does make the problem go away (but I don't know why). diff --git a/sbin/dhclient/dhclient.c b/sbin/dhclient/dhclient.c index c5d197ee274..042254d7798 100644 --- a/sbin/dhclient/dhclient.c +++ b/sbin/dhclient/dhclient.c @@ -345,6 +345,7 @@ rtm_dispatch(struct interface_info *ifi, struct rt_msghdr *rtm) struct ifa_msghdr *ifam; struct if_ieee80211_data *ifie; uint32_t oldmtu; + int oldlinkup; switch (rtm->rtm_type) { case RTM_PROPOSAL: @@ -390,11 +391,13 @@ rtm_dispatch(struct interface_info *ifi, struct rt_msghdr *rtm) oldmtu = ifi->mtu; interface_state(ifi); - if (oldmtu == ifi->mtu) - quit = RESTART; - else - log_debug("%s: MTU change RTM_IFINFO ignored", - log_procname); + if (LINK_STATE_IS_UP(ifi->link_state) != oldlinkup) { + if (oldmtu == ifi->mtu) + quit = RESTART; + else + log_debug("%s: MTU change RTM_IFINFO ignored", + log_procname); + } break; case RTM_80211INFO: Here's the test script I ran from both bsd.rd's: #!/bin/sh [ -n "$1" ] || { echo "usage"; exit 1; } exec > test.$1 2>&1 set -x route monitor >route-monitor.$1 & dhclient vio0 sleep 1 ifconfig vio0 ping -c 1 1.1.1.1 ifconfig vio0 -soii sleep 1 ping -c 1 1.1.1.1 ifconfig vio0 kill -INT %1 and the results. first, "bad": $ cat test.bad + dhclient vio0 + route monitor + > route-monitor.bad + sleep 1 + ifconfig vio0 vio0: flags=808843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST,AUTOCONF4> mtu 1500 lladdr 96:00:00:34:06:8e llprio 3 groups: egress media: Ethernet autoselect status: active inet 95.217.7.62 netmask 0xffffffff + ping -c 1 1.1.1.1 PING 1.1.1.1 (1.1.1.1): 56 data bytes 64 bytes from 1.1.1.1: icmp_seq=0 ttl=57 time=18.778 ms --- 1.1.1.1 ping statistics --- 1 packets transmitted, 1 packets received, 0.0% packet loss round-trip min/avg/max/std-dev = 18.778/18.778/18.778/0.000 ms + ifconfig vio0 -soii + sleep 1 + ping -c 1 1.1.1.1 ping: sendmsg: Invalid argument PING 1.1.1.1 (1.1.1.1): 56 data bytes ping: wrote 1.1.1.1 64 chars, ret=-1 --- 1.1.1.1 ping statistics --- 1 packets transmitted, 0 packets received, 100.0% packet loss + ifconfig vio0 vio0: flags=c08843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST,INET6_NOSOII,AUTOCONF4> mtu 1500 lladdr 96:00:00:34:06:8e llprio 3 groups: egress media: Ethernet autoselect status: active inet 95.217.7.62 netmask 0xffffffff + kill -INT %1 $ cat route-monitor.bad got message of size 168 on Fri Oct 25 11:45:38 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> got message of size 168 on Fri Oct 25 11:45:38 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> got message of size 168 on Fri Oct 25 11:45:38 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> got message of size 168 on Fri Oct 25 11:45:38 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> got message of size 96 on Fri Oct 25 11:45:38 2019 RTM_PROPOSAL: config proposal: len 96, source dhcp table 0, ifidx 1, pid: 22261, seq -593891804, errno 0 flags:<UP,DONE,PROTO3> fmask: use: 0 mtu: 0 expire: 0 locks: inits: Static Routes: Domain search: Domain Name Servers: got message of size 96 on Fri Oct 25 11:45:38 2019 RTM_NEWADDR: address being added to iface: len 96, metric 0, flags: sockaddrs: <NETMASK,IFP,IFA,BRD> 255.255.255.255 96:00:00:34:06:8e 95.217.7.62 0.0.0.0 got message of size 192 on Fri Oct 25 11:45:38 2019 RTM_ADD: Add Route: len 192, priority 1, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<UP,HOST,DONE,LLINFO,LOCAL> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,IFP,IFA> 95.217.7.62 96:00:00:34:06:8e 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:38 2019 RTM_ADD: Add Route: len 192, priority 4, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<UP,DONE,CLONING,CONNECTED> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 95.217.7.62 95.217.7.62 255.255.255.255 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:38 2019 RTM_ADD: Add Route: len 192, priority 8, table 0, ifidx 1, pid: 678, seq 0, errno 0 flags:<UP,DONE,CLONING,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 172.31.1.1 95.217.7.62 255.255.255.255 96:00:00:34:06:8e 95.217.7.62 got message of size 144 on Fri Oct 25 11:45:38 2019 RTM_ADD: Add Route: len 144, priority 0, table 0, ifidx 1, pid: 678, seq 0, errno 17 flags:<CLONING,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK> 172.31.1.1 95.217.7.62 255.255.255.255 got message of size 192 on Fri Oct 25 11:45:38 2019 RTM_ADD: Add Route: len 192, priority 7, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<UP,HOST,DONE,LLINFO,CLONED> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,IFP,IFA> 172.31.1.1 link#1 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:38 2019 RTM_ADD: Add Route: len 192, priority 8, table 0, ifidx 1, pid: 678, seq 0, errno 0 flags:<UP,GATEWAY,DONE,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:38 2019 RTM_GET: Report Metrics: len 192, priority 8, table 0, ifidx 1, pid: 678, seq -1688123477, errno 0 flags:<UP,GATEWAY,DONE,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:38 2019 RTM_GET: Report Metrics: len 192, priority 8, table 0, ifidx 1, pid: 678, seq -2029380539, errno 0 flags:<UP,GATEWAY,DONE,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:39 2019 RTM_RESOLVE: Route created by cloning: len 192, priority 7, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<UP,HOST,DONE,LLINFO,CLONED,CACHED> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,IFP,IFA> 172.31.1.1 d2:74:7f:6e:37:e3 96:00:00:34:06:8e 95.217.7.62 got message of size 168 on Fri Oct 25 11:45:39 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST,INET6_NOSOII> got message of size 192 on Fri Oct 25 11:45:39 2019 RTM_GET: Report Metrics: len 192, priority 8, table 0, ifidx 1, pid: 678, seq 870724543, errno 0 flags:<UP,GATEWAY,DONE,STATIC> fmask: use: 1 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 96:00:00:34:06:8e 95.217.7.62 got message of size 208 on Fri Oct 25 11:45:39 2019 RTM_DELETE: Delete Route: len 208, priority 7, table 0, ifidx 1, pid: 678, seq 0, errno 0 flags:<UP,HOST,DONE,LLINFO,CLONED,CACHED> fmask: use: 2 mtu: 0 expire: 1200 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 172.31.1.1 link#1 255.255.255.255 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:39 2019 RTM_DELETE: Delete Route: len 192, priority 7, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<HOST,DONE,CLONED,CACHED> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,IFP,IFA> 172.31.1.1 link#1 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:39 2019 RTM_DELETE: Delete Route: len 192, priority 8, table 0, ifidx 1, pid: 678, seq 1, errno 0 flags:<DONE,CLONING,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 172.31.1.1 95.217.7.62 255.255.255.255 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:39 2019 RTM_ADD: Add Route: len 192, priority 8, table 0, ifidx 1, pid: 678, seq 0, errno 0 flags:<UP,DONE,CLONING,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 172.31.1.1 95.217.7.62 255.255.255.255 96:00:00:34:06:8e 95.217.7.62 got message of size 144 on Fri Oct 25 11:45:39 2019 RTM_ADD: Add Route: len 144, priority 0, table 0, ifidx 1, pid: 678, seq 0, errno 17 flags:<CLONING,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK> 172.31.1.1 95.217.7.62 255.255.255.255 got message of size 192 on Fri Oct 25 11:45:39 2019 RTM_ADD: Add Route: len 192, priority 7, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<UP,HOST,DONE,LLINFO,CLONED> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,IFP,IFA> 172.31.1.1 link#1 96:00:00:34:06:8e 95.217.7.62 got message of size 160 on Fri Oct 25 11:45:39 2019 RTM_ADD: Add Route: len 160, priority 0, table 0, ifidx 1, pid: 678, seq 0, errno 17 flags:<GATEWAY,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 95.217.7.62 got message of size 192 on Fri Oct 25 11:45:39 2019 RTM_GET: Report Metrics: len 192, priority 8, table 0, ifidx 1, pid: 678, seq -1044169088, errno 0 flags:<UP,GATEWAY,DONE,STATIC> fmask: use: 1 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 96:00:00:34:06:8e 95.217.7.62 then, "good": $ cat test.good + dhclient vio0 + route monitor + > route-monitor.good + sleep 1 + ifconfig vio0 vio0: flags=808843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST,AUTOCONF4> mtu 1500 lladdr 96:00:00:34:06:8e llprio 3 groups: egress media: Ethernet autoselect status: active inet 95.217.7.62 netmask 0xffffffff + ping -c 1 1.1.1.1 PING 1.1.1.1 (1.1.1.1): 56 data bytes 64 bytes from 1.1.1.1: icmp_seq=0 ttl=57 time=7.957 ms --- 1.1.1.1 ping statistics --- 1 packets transmitted, 1 packets received, 0.0% packet loss round-trip min/avg/max/std-dev = 7.957/7.957/7.957/0.000 ms + ifconfig vio0 -soii + sleep 1 + ping -c 1 1.1.1.1 PING 1.1.1.1 (1.1.1.1): 56 data bytes 64 bytes from 1.1.1.1: icmp_seq=0 ttl=57 time=7.947 ms --- 1.1.1.1 ping statistics --- 1 packets transmitted, 1 packets received, 0.0% packet loss round-trip min/avg/max/std-dev = 7.947/7.947/7.947/0.000 ms + ifconfig vio0 vio0: flags=c08843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST,INET6_NOSOII,AUTOCONF4> mtu 1500 lladdr 96:00:00:34:06:8e llprio 3 groups: egress media: Ethernet autoselect status: active inet 95.217.7.62 netmask 0xffffffff + kill -INT %1 $ cat route-monitor.good got message of size 168 on Fri Oct 25 11:47:05 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> got message of size 168 on Fri Oct 25 11:47:05 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> got message of size 168 on Fri Oct 25 11:47:05 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> got message of size 168 on Fri Oct 25 11:47:05 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> got message of size 96 on Fri Oct 25 11:47:05 2019 RTM_PROPOSAL: config proposal: len 96, source dhcp table 0, ifidx 1, pid: 93221, seq -1235616654, errno 0 flags:<UP,DONE,PROTO3> fmask: use: 0 mtu: 0 expire: 0 locks: inits: Static Routes: Domain search: Domain Name Servers: got message of size 96 on Fri Oct 25 11:47:05 2019 RTM_NEWADDR: address being added to iface: len 96, metric 0, flags: sockaddrs: <NETMASK,IFP,IFA,BRD> 255.255.255.255 96:00:00:34:06:8e 95.217.7.62 0.0.0.0 got message of size 192 on Fri Oct 25 11:47:05 2019 RTM_ADD: Add Route: len 192, priority 1, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<UP,HOST,DONE,LLINFO,LOCAL> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,IFP,IFA> 95.217.7.62 96:00:00:34:06:8e 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:47:05 2019 RTM_ADD: Add Route: len 192, priority 4, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<UP,DONE,CLONING,CONNECTED> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 95.217.7.62 95.217.7.62 255.255.255.255 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:47:05 2019 RTM_ADD: Add Route: len 192, priority 8, table 0, ifidx 1, pid: 56044, seq 0, errno 0 flags:<UP,DONE,CLONING,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 172.31.1.1 95.217.7.62 255.255.255.255 96:00:00:34:06:8e 95.217.7.62 got message of size 144 on Fri Oct 25 11:47:05 2019 RTM_ADD: Add Route: len 144, priority 0, table 0, ifidx 1, pid: 56044, seq 0, errno 17 flags:<CLONING,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK> 172.31.1.1 95.217.7.62 255.255.255.255 got message of size 192 on Fri Oct 25 11:47:05 2019 RTM_ADD: Add Route: len 192, priority 7, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<UP,HOST,DONE,LLINFO,CLONED> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,IFP,IFA> 172.31.1.1 link#1 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:47:05 2019 RTM_ADD: Add Route: len 192, priority 8, table 0, ifidx 1, pid: 56044, seq 0, errno 0 flags:<UP,GATEWAY,DONE,STATIC> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:47:05 2019 RTM_RESOLVE: Route created by cloning: len 192, priority 7, table 0, ifidx 1, pid: 0, seq 0, errno 0 flags:<UP,HOST,DONE,LLINFO,CLONED,CACHED> fmask: use: 0 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,IFP,IFA> 172.31.1.1 d2:74:7f:6e:37:e3 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:47:05 2019 RTM_GET: Report Metrics: len 192, priority 8, table 0, ifidx 1, pid: 56044, seq 1611749725, errno 0 flags:<UP,GATEWAY,DONE,STATIC> fmask: use: 4 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 96:00:00:34:06:8e 95.217.7.62 got message of size 192 on Fri Oct 25 11:47:05 2019 RTM_GET: Report Metrics: len 192, priority 8, table 0, ifidx 1, pid: 56044, seq 1590428816, errno 0 flags:<UP,GATEWAY,DONE,STATIC> fmask: use: 4 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 96:00:00:34:06:8e 95.217.7.62 got message of size 168 on Fri Oct 25 11:47:06 2019 RTM_IFINFO: iface status change: len 168, if# 1, name: vio0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST,INET6_NOSOII> got message of size 192 on Fri Oct 25 11:47:06 2019 RTM_GET: Report Metrics: len 192, priority 8, table 0, ifidx 1, pid: 56044, seq -2015332144, errno 0 flags:<UP,GATEWAY,DONE,STATIC> fmask: use: 5 mtu: 0 expire: 0 locks: inits: sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA> 0.0.0.0 172.31.1.1 0.0.0.0 96:00:00:34:06:8e 95.217.7.62 -- Lauri Tirkkonen | lotheac @ IRCnet