Re: recent dhcpcd looping on ppp0
On 2014-09-29 19:29, Frank Kardel wrote: Much better now. The busy wait loop is now gone. A new dhcpcd with this fix has been imported into -current. Roy
Re: recent dhcpcd looping on ppp0
Hi Frank
On 2014-09-28 22:58, Frank Kardel wrote:
On 09/28/14 23:17, Roy Marples wrote:
On Sunday 28 Sep 2014 22:06:47 Roy Marples wrote:
Going to guess that ppp0 doesn't have a carrier status OR IFF_RUNNING
set?
The attached patch should reduce the log spam, let me know how it
works out.
Errm, this patch should do better!
Roy
Well, less spam, but still
- busy wait (repeated count goes up to ~300k)
Sep 28 23:50:05 Andromeda dhcpcd[1101]: ppp0: unknown carrier
Sep 28 23:50:05 Andromeda dhcpcd[1101]: ppp0: carrier_status:
Inappropriate ioctl for device
Sep 28 23:50:14 Andromeda syslogd[1251]: last message repeated 12776
times
- a flurry of routing messages (probably same number of as syslog
entries)
got message of size 152 on Sun Sep 28 23:50:10 2014
RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown,
flags: UP,PTP,MULTICAST
got message of size 152 on Sun Sep 28 23:50:10 2014
Yes, these messages are being triggerd by a flurry of routing messages.
This is probably a bug in NetBSD somewhere and the attached patch should
pretty much silence the warnings down to one n dhcpcd until the link
actually comes up.
Let me know how this one works!
Thanks
RoyIndex: dhcpcd.c
==
--- dhcpcd.c
+++ dhcpcd.c
@@ -547,19 +547,23 @@
* dhcpcd has already set it.
*
* So we check the flags now. If IFF_UP is still not set
* then we should expect an accompanying link_down message */
if_setflag(ifp, 0); /* will set ifp-flags */
+ ifp-options-options = ~DHCPCD_LINK_WARNED;
break;
default:
ifp-flags = flags;
+ ifp-options-options = ~DHCPCD_LINK_WARNED;
}
- if (carrier == LINK_UNKNOWN)
- syslog(LOG_ERR, %s: carrier_status: %m, ifname);
- /* IFF_RUNNING is checked, if needed, earlier and is OS dependant */
- else if (carrier == LINK_DOWN || (ifp-flags IFF_UP) == 0) {
+ if (carrier == LINK_UNKNOWN) {
+ if (!ifp-options-options DHCPCD_LINK_WARNED) {
+ syslog(LOG_ERR, %s: carrier_status: %m, ifname);
+ ifp-options-options |= DHCPCD_LINK_WARNED;
+ }
+ } else if (carrier == LINK_DOWN || (ifp-flags IFF_UP) == 0) {
if (ifp-carrier != LINK_DOWN) {
if (ifp-carrier == LINK_UP)
syslog(LOG_INFO, %s: carrier lost, ifp-name);
ifp-carrier = LINK_DOWN;
script_runreason(ifp, NOCARRIER);
@@ -648,21 +652,26 @@
if (ifo-options DHCPCD_LINK) {
link_retry:
switch (ifp-carrier) {
case LINK_UP:
+ ifo-options = ~DHCPCD_LINK_WARNED;
break;
case LINK_DOWN:
+ ifo-options = ~DHCPCD_LINK_WARNED;
syslog(LOG_INFO, %s: waiting for carrier, ifp-name);
return;
case LINK_UNKNOWN:
/* No media state available, so we loop until
* IFF_UP and IFF_RUNNING are set. */
ifp-carrier = if_carrier(ifp);
if (ifp-carrier != LINK_UNKNOWN)
goto link_retry;
- syslog(LOG_INFO, %s: unknown carrier, ifp-name);
+ if (!(ifo-options DHCPCD_LINK_WARNED)) {
+syslog(LOG_INFO, %s: unknown carrier, ifp-name);
+ifo-options |= DHCPCD_LINK_WARNED;
+ }
tv.tv_sec = 0;
tv.tv_usec = 100;
eloop_timeout_add_tv(ifp-ctx-eloop, tv,
dhcpcd_startinterface, ifp);
return;
Index: if-options.h
==
--- if-options.h
+++ if-options.h
@@ -104,10 +104,11 @@
#define DHCPCD_DHCP (1ULL 49)
#define DHCPCD_DHCP6 (1ULL 50)
#define DHCPCD_NOPFXDLG (1ULL 51)
#define DHCPCD_PFXDLGONLY (1ULL 52)
#define DHCPCD_PFXDLGMIX (1ULL 53)
+#define DHCPCD_LINK_WARNED (1ULL 54)
extern const struct option cf_options[];
struct if_sla {
char ifname[IF_NAMESIZE];
Re: recent dhcpcd looping on ppp0
On 2014-09-29 11:33, Roy Marples wrote:
Going to guess that ppp0 doesn't have a carrier status OR
IFF_RUNNING set?
The attached patch should reduce the log spam, let me know how it
works out.
Errm, this patch should do better!
Well, less spam, but still
- busy wait (repeated count goes up to ~300k)
Sep 28 23:50:05 Andromeda dhcpcd[1101]: ppp0: unknown carrier
Sep 28 23:50:05 Andromeda dhcpcd[1101]: ppp0: carrier_status:
Inappropriate ioctl for device
Sep 28 23:50:14 Andromeda syslogd[1251]: last message repeated 12776
times
- a flurry of routing messages (probably same number of as syslog
entries)
got message of size 152 on Sun Sep 28 23:50:10 2014
RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown,
flags: UP,PTP,MULTICAST
got message of size 152 on Sun Sep 28 23:50:10 2014
Yes, these messages are being triggerd by a flurry of routing messages.
This is probably a bug in NetBSD somewhere and the attached patch
should pretty much silence the warnings down to one n dhcpcd until the
link actually comes up.
So the flurry of messages is triggered by dhcpcd still (thanks
jmcneill!).
This patch should fix it and all should now be well.
RoyIndex: dhcpcd.c
==
--- dhcpcd.c
+++ dhcpcd.c
@@ -552,14 +552,14 @@
break;
default:
ifp-flags = flags;
}
- if (carrier == LINK_UNKNOWN)
- syslog(LOG_ERR, %s: carrier_status: %m, ifname);
- /* IFF_RUNNING is checked, if needed, earlier and is OS dependant */
- else if (carrier == LINK_DOWN || (ifp-flags IFF_UP) == 0) {
+ if (carrier == LINK_UNKNOWN) {
+ if (errno != ENOTTY) /* For example a PPP link on BSD */
+ syslog(LOG_ERR, %s: carrier_status: %m, ifname);
+ } else if (carrier == LINK_DOWN || (ifp-flags IFF_UP) == 0) {
if (ifp-carrier != LINK_DOWN) {
if (ifp-carrier == LINK_UP)
syslog(LOG_INFO, %s: carrier lost, ifp-name);
ifp-carrier = LINK_DOWN;
script_runreason(ifp, NOCARRIER);
@@ -638,11 +638,10 @@
{
struct interface *ifp = arg;
struct if_options *ifo = ifp-options;
size_t i;
char buf[DUID_LEN * 3];
- struct timeval tv;
pre_start(ifp);
if (if_up(ifp) == -1)
syslog(LOG_ERR, %s: if_up: %m, ifp-name);
@@ -653,20 +652,19 @@
break;
case LINK_DOWN:
syslog(LOG_INFO, %s: waiting for carrier, ifp-name);
return;
case LINK_UNKNOWN:
- /* No media state available, so we loop until
- * IFF_UP and IFF_RUNNING are set. */
+ /* No media state available.
+ * Any change on state such as IFF_UP and IFF_RUNNING
+ * should be reported to us via the route socket
+ * as we've done the best we can to bring the interface
+ * up at this point. */
ifp-carrier = if_carrier(ifp);
if (ifp-carrier != LINK_UNKNOWN)
goto link_retry;
syslog(LOG_INFO, %s: unknown carrier, ifp-name);
- tv.tv_sec = 0;
- tv.tv_usec = 100;
- eloop_timeout_add_tv(ifp-ctx-eloop, tv,
- dhcpcd_startinterface, ifp);
return;
}
}
if (ifo-options (DHCPCD_DUID | DHCPCD_IPV6)) {
Re: recent dhcpcd looping on ppp0
Much better now. The busy wait loop is now gone. Thanks ! Frank On 09/29/14 14:03, Roy Marples wrote: On 2014-09-29 11:33, Roy Marples wrote: Going to guess that ppp0 doesn't have a carrier status OR IFF_RUNNING set? The attached patch should reduce the log spam, let me know how it works out. Errm, this patch should do better! Well, less spam, but still - busy wait (repeated count goes up to ~300k) Sep 28 23:50:05 Andromeda dhcpcd[1101]: ppp0: unknown carrier Sep 28 23:50:05 Andromeda dhcpcd[1101]: ppp0: carrier_status: Inappropriate ioctl for device Sep 28 23:50:14 Andromeda syslogd[1251]: last message repeated 12776 times - a flurry of routing messages (probably same number of as syslog entries) got message of size 152 on Sun Sep 28 23:50:10 2014 RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown, flags: UP,PTP,MULTICAST got message of size 152 on Sun Sep 28 23:50:10 2014 Yes, these messages are being triggerd by a flurry of routing messages. This is probably a bug in NetBSD somewhere and the attached patch should pretty much silence the warnings down to one n dhcpcd until the link actually comes up. So the flurry of messages is triggered by dhcpcd still (thanks jmcneill!). This patch should fix it and all should now be well. Roy
Re: recent dhcpcd looping on ppp0
Hi Frank
On Sunday 28 Sep 2014 16:14:01 Frank Kardel wrote:
The recent dhcpcd version (-current around 20140927) seems to be looping
on ppp* interfaces.
Sep 28 15:14:11 Andromeda dhcpcd[3259]: ppp0: unknown carrier
Sep 28 15:14:11 Andromeda dhcpcd[3259]: ppp0: carrier_status:
Inappropriate ioctl for device
Sep 28 15:14:11 Andromeda dhcpcd[3259]: ppp0: unknown carrier
Sep 28 15:14:11 Andromeda dhcpcd[3259]: ppp0: carrier_status:
Inappropriate ioctl for device
Sep 28 15:14:11 Andromeda dhcpcd[3259]: ppp0: unknown carrier
Sep 28 15:14:11 Andromeda dhcpcd[3259]: ppp0: carrier_status:
Inappropriate ioctl for device
Sep 28 15:14:11 Andromeda dhcpcd[3259]: ppp0: unknown carrier
Sep 28 15:14:11 Andromeda dhcpcd[3259]: ppp0: carrier_status:
Inappropriate ioctl for device
Going to guess that ppp0 doesn't have a carrier status OR IFF_RUNNING set?
The attached patch should reduce the log spam, let me know how it works out.
Thanks
RoyIndex: dhcpcd.c
==
--- dhcpcd.c
+++ dhcpcd.c
@@ -547,13 +547,15 @@
* dhcpcd has already set it.
*
* So we check the flags now. If IFF_UP is still not set
* then we should expect an accompanying link_down message */
if_setflag(ifp, 0); /* will set ifp-flags */
+ ifp-options-options = ~DHCPCD_LINK_WARNED;
break;
default:
ifp-flags = flags;
+ ifp-options-options = ~DHCPCD_LINK_WARNED;
}
if (carrier == LINK_UNKNOWN)
syslog(LOG_ERR, %s: carrier_status: %m, ifname);
/* IFF_RUNNING is checked, if needed, earlier and is OS dependant */
@@ -648,21 +650,26 @@
if (ifo-options DHCPCD_LINK) {
link_retry:
switch (ifp-carrier) {
case LINK_UP:
+ ifo-options = ~DHCPCD_LINK_WARNED;
break;
case LINK_DOWN:
+ ifo-options = ~DHCPCD_LINK_WARNED;
syslog(LOG_INFO, %s: waiting for carrier, ifp-name);
return;
case LINK_UNKNOWN:
/* No media state available, so we loop until
* IFF_UP and IFF_RUNNING are set. */
ifp-carrier = if_carrier(ifp);
if (ifp-carrier != LINK_UNKNOWN)
goto link_retry;
- syslog(LOG_INFO, %s: unknown carrier, ifp-name);
+ if (ifo-options DHCPCD_LINK_WARNED)
+syslog(LOG_INFO, %s: unknown carrier, ifp-name);
+ else
+ifo-options |= DHCPCD_LINK_WARNED;
tv.tv_sec = 0;
tv.tv_usec = 100;
eloop_timeout_add_tv(ifp-ctx-eloop, tv,
dhcpcd_startinterface, ifp);
return;
Index: if-options.h
==
--- if-options.h
+++ if-options.h
@@ -104,10 +104,11 @@
#define DHCPCD_DHCP (1ULL 49)
#define DHCPCD_DHCP6 (1ULL 50)
#define DHCPCD_NOPFXDLG (1ULL 51)
#define DHCPCD_PFXDLGONLY (1ULL 52)
#define DHCPCD_PFXDLGMIX (1ULL 53)
+#define DHCPCD_LINK_WARNED (1ULL 54)
extern const struct option cf_options[];
struct if_sla {
char ifname[IF_NAMESIZE];
Re: recent dhcpcd looping on ppp0
In article 1559176.gihfizv...@uberpc.marples.name, Roy Marples r...@marples.name wrote: + if (ifo-options DHCPCD_LINK_WARNED) == 0? + syslog(LOG_INFO, %s: unknown carrier, ifp-name); + else + ifo-options |= DHCPCD_LINK_WARNED; christos
Re: recent dhcpcd looping on ppp0
On 09/28/14 23:17, Roy Marples wrote: On Sunday 28 Sep 2014 22:06:47 Roy Marples wrote: Going to guess that ppp0 doesn't have a carrier status OR IFF_RUNNING set? The attached patch should reduce the log spam, let me know how it works out. Errm, this patch should do better! Roy Well, less spam, but still - busy wait (repeated count goes up to ~300k) Sep 28 23:50:05 Andromeda dhcpcd[1101]: ppp0: unknown carrier Sep 28 23:50:05 Andromeda dhcpcd[1101]: ppp0: carrier_status: Inappropriate ioctl for device Sep 28 23:50:14 Andromeda syslogd[1251]: last message repeated 12776 times - a flurry of routing messages (probably same number of as syslog entries) got message of size 152 on Sun Sep 28 23:50:10 2014 RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown, flags: UP,PTP,MULTICAST got message of size 152 on Sun Sep 28 23:50:10 2014 RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown, flags: UP,PTP,MULTICAST got message of size 152 on Sun Sep 28 23:50:10 2014 RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown, flags: UP,PTP,MULTICAST got message of size 152 on Sun Sep 28 23:50:10 2014 RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown, flags: UP,PTP,MULTICAST got message of size 152 on Sun Sep 28 23:50:10 2014 RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown, flags: UP,PTP,MULTICAST got message of size 152 on Sun Sep 28 23:50:10 2014 RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown, flags: UP,PTP,MULTICAST got message of size 152 on Sun Sep 28 23:50:10 2014 RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown, flags: UP,PTP,MULTICAST got message of size 152 on Sun Sep 28 23:50:10 2014 RTM_IFINFO: iface status change: len 152, if# 6, carrier: unknown, flags: UP,PTP,MULTICAST leading to busy routing message aware daemons (named, mdnsd) As a bonus (not necessarily related) a panic: Sep 28 23:36:30 Andromeda /netbsd: panic: kernel diagnostic assertion c-c_cpu-cc_lwp == curlwp || c-c_cpu-cc_active != c failed: file /usr/srccur/src/sys/kern/kern_timeout.c, line 313 Sep 28 23:36:30 Andromeda /netbsd: cpu1: Begin traceback... Sep 28 23:36:30 Andromeda /netbsd: vpanic() at netbsd:vpanic+0x13c Sep 28 23:36:30 Andromeda /netbsd: kern_assert() at netbsd:kern_assert+0x4f Sep 28 23:36:30 Andromeda /netbsd: callout_destroy() at netbsd:callout_destroy+0x74 Sep 28 23:36:30 Andromeda /netbsd: in6_delmulti() at netbsd:in6_delmulti+0x177 Sep 28 23:36:30 Andromeda /netbsd: in6_leavegroup() at netbsd:in6_leavegroup+0x15 Sep 28 23:36:30 Andromeda /netbsd: ip6_freemoptions() at netbsd:ip6_freemoptions+0x30 Sep 28 23:36:30 Andromeda /netbsd: in6_pcbdetach() at netbsd:in6_pcbdetach+0xd7 Sep 28 23:36:30 Andromeda /netbsd: udp6_detach_wrapper() at netbsd:udp6_detach_wrapper+0x3f Sep 28 23:36:30 Andromeda /netbsd: soclose() at netbsd:soclose+0x63 Sep 28 23:36:30 Andromeda /netbsd: soo_close() at netbsd:soo_close+0x16 Sep 28 23:36:30 Andromeda /netbsd: closef() at netbsd:closef+0x54 Sep 28 23:36:30 Andromeda /netbsd: fd_close() at netbsd:fd_close+0x19f Sep 28 23:36:30 Andromeda /netbsd: sys_close() at netbsd:sys_close+0x20 Sep 28 23:36:30 Andromeda /netbsd: syscall() at netbsd:syscall+0x9a Sep 28 23:36:30 Andromeda /netbsd: --- syscall (number 6) --- Sep 28 23:36:30 Andromeda /netbsd: 7f7ff743c46a: Sep 28 23:36:30 Andromeda /netbsd: cpu1: End traceback... Best regards, Frank
