NetBSD Problem Report #52701

From gson@gson.org  Sun Nov  5 13:33:59 2017
Return-Path: <gson@gson.org>
Received: from mail.netbsd.org (mail.netbsd.org [199.233.217.200])
	(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
	(Client CN "mail.NetBSD.org", Issuer "mail.NetBSD.org CA" (not verified))
	by mollari.NetBSD.org (Postfix) with ESMTPS id 8C4647A1CD
	for <gnats-bugs@gnats.NetBSD.org>; Sun,  5 Nov 2017 13:33:59 +0000 (UTC)
Message-Id: <20171105133353.07298989E67@guava.gson.org>
Date: Sun,  5 Nov 2017 15:33:53 +0200 (EET)
From: gson@gson.org (Andreas Gustafsson)
Reply-To: gson@gson.org (Andreas Gustafsson)
To: gnats-bugs@NetBSD.org
Subject: rtadvd logs thousands of syslog messages
X-Send-Pr-Version: 3.95

>Number:         52701
>Category:       bin
>Synopsis:       rtadvd logs thousands of syslog messages
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    bin-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Sun Nov 05 13:35:00 +0000 2017
>Closed-Date:    
>Last-Modified:  Thu Feb 08 08:38:53 +0000 2018
>Originator:     Andreas Gustafsson
>Release:        NetBSD-current, source date >= 2017.02.28.04.47.41
>Organization:

>Environment:
System: NetBSD
Architecture: i386
Machine: i386
>Description:

While reviewing console output logs from the test runs on the TNF
testbed in the course of investigating an unrelated bug, I noticed
that some of the logs included messages like the following:

  Nov  2 18:40:30	 syslogd[189]: last message repeated 78108 times
  Nov  2 18:50:30	 syslogd[189]: last message repeated 116025 times
  Nov  2 19:00:30	 syslogd[189]: last message repeated 112322 times
  Nov  2 19:10:30	 syslogd[189]: last message repeated 111487 times
  Nov  2 19:20:31	 syslogd[189]: last message repeated 119638 times
  Nov  2 19:30:31	 syslogd[189]: last message repeated 113491 times
  Nov  2 19:40:31	 syslogd[189]: last message repeated 112569 times
  Nov  2 19:50:31	 syslogd[189]: last message repeated 112543 times
  Nov  2 20:00:33	 syslogd[189]: last message repeated 133812 times
  Nov  2 20:10:33	 syslogd[189]: last message repeated 137892 times
  Nov  2 20:20:33	 syslogd[189]: last message repeated 144270 times
  Nov  2 20:30:34	 syslogd[189]: last message repeated 140495 times
  Nov  2 20:40:34	 syslogd[189]: last message repeated 135550 times
  Nov  2 20:50:34	 syslogd[189]: last message repeated 139106 times
  Nov  2 21:00:34	 syslogd[189]: last message repeated 139265 times

These particular ones are are from

  http://releng.netbsd.org/b5reports/i386/build/2017.11.01.21.13.26/test.log

As far as I can tell from the log, the message being repeated is:

  Nov  2 11:09:07  rtadvd[1478]: main: poll: Socket is not connected

The messages first appeared in February, in

  http://releng.netbsd.org/b5reports/i386/build/2017.02.28.04.47.41/test.log

but since they do not appear in every test run, this does not identify
the exact commit that triggered the problem.

>How-To-Repeat:

>Fix:

>Release-Note:

>Audit-Trail:
From: "J. Hannken-Illjes" <hannken@eis.cs.tu-bs.de>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: bin/52701: rtadvd logs thousands of syslog messages
Date: Sun, 5 Nov 2017 15:48:07 +0100

 --Apple-Mail=_D998CD31-DB37-4159-9C9D-F768E4B92A7D
 Content-Transfer-Encoding: 7bit
 Content-Type: text/plain;
 	charset=us-ascii

 For some time I have this local change and it helped me a lot.

 --
 J. Hannken-Illjes - hannken@eis.cs.tu-bs.de - TU Braunschweig (Germany)

 --Apple-Mail=_D998CD31-DB37-4159-9C9D-F768E4B92A7D
 Content-Disposition: attachment;
 	filename=t_ra.diff
 Content-Type: application/octet-stream;
 	x-unix-mode=0644;
 	name="t_ra.diff"
 Content-Transfer-Encoding: 7bit

 Index: t_ra.sh
 ===================================================================
 RCS file: /cvsroot/src/tests/net/ndp/t_ra.sh,v
 retrieving revision 1.29
 diff -p -u -2 -r1.29 t_ra.sh
 --- t_ra.sh	22 Jun 2017 09:56:48 -0000	1.29
 +++ t_ra.sh	5 Nov 2017 14:46:30 -0000
 @@ -288,4 +288,8 @@ ra_flush_prefix_entries_cleanup()
  {

 +	if [ -f ${PIDFILE} ]; then
 +		kill -TERM `cat ${PIDFILE}`
 +		wait_term ${PIDFILE}
 +	fi
  	$DEBUG && dump
  	cleanup
 @@ -345,4 +349,8 @@ ra_flush_defrouter_entries_cleanup()
  {

 +	if [ -f ${PIDFILE} ]; then
 +		kill -TERM `cat ${PIDFILE}`
 +		wait_term ${PIDFILE}
 +	fi
  	$DEBUG && dump
  	cleanup
 @@ -772,4 +780,8 @@ ra_defrouter_expiration_cleanup()
  {

 +	if [ -f ${PIDFILE} ]; then
 +		kill -TERM `cat ${PIDFILE}`
 +		wait_term ${PIDFILE}
 +	fi
  	$DEBUG && dump
  	cleanup
 @@ -837,4 +849,8 @@ ra_prefix_expiration_cleanup()
  {

 +	if [ -f ${PIDFILE} ]; then
 +		kill -TERM `cat ${PIDFILE}`
 +		wait_term ${PIDFILE}
 +	fi
  	$DEBUG && dump
  	cleanup

 --Apple-Mail=_D998CD31-DB37-4159-9C9D-F768E4B92A7D--

From: "Ryota Ozaki" <ozaki-r@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/52701 CVS commit: src/tests/net/ndp
Date: Mon, 6 Nov 2017 10:51:40 +0000

 Module Name:	src
 Committed By:	ozaki-r
 Date:		Mon Nov  6 10:51:40 UTC 2017

 Modified Files:
 	src/tests/net/ndp: t_ra.sh

 Log Message:
 Kill rtadvd surely even if the tests fail in the middle

 It may help PR bin/52701.


 To generate a diff of this commit:
 cvs rdiff -u -r1.29 -r1.30 src/tests/net/ndp/t_ra.sh

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

From: Ryota Ozaki <ozaki-r@netbsd.org>
To: "gnats-bugs@NetBSD.org" <gnats-bugs@netbsd.org>
Cc: gnats-admin@netbsd.org, netbsd-bugs@netbsd.org, 
	Andreas Gustafsson <gson@gson.org>
Subject: Re: bin/52701: rtadvd logs thousands of syslog messages
Date: Mon, 6 Nov 2017 19:58:55 +0900

 On Sun, Nov 5, 2017 at 11:50 PM, J. Hannken-Illjes
 <hannken@eis.cs.tu-bs.de> wrote:
 > The following reply was made to PR bin/52701; it has been noted by GNATS.
 >
 > From: "J. Hannken-Illjes" <hannken@eis.cs.tu-bs.de>
 > To: gnats-bugs@NetBSD.org
 > Cc:
 > Subject: Re: bin/52701: rtadvd logs thousands of syslog messages
 > Date: Sun, 5 Nov 2017 15:48:07 +0100
 >
 >  --Apple-Mail=_D998CD31-DB37-4159-9C9D-F768E4B92A7D
 >  Content-Transfer-Encoding: 7bit
 >  Content-Type: text/plain;
 >         charset=us-ascii
 >
 >  For some time I have this local change and it helped me a lot.

 Thanks. I added similar cleanup codes to the tests.

 I think that the real fix is to suppress rtadvd on a rump kernel
 from dumping logs to the host, but I have no idea how to do it.

   ozaki-r

 >
 >  --
 >  J. Hannken-Illjes - hannken@eis.cs.tu-bs.de - TU Braunschweig (Germany)
 >
 >  --Apple-Mail=_D998CD31-DB37-4159-9C9D-F768E4B92A7D
 >  Content-Disposition: attachment;
 >         filename=t_ra.diff
 >  Content-Type: application/octet-stream;
 >         x-unix-mode=0644;
 >         name="t_ra.diff"
 >  Content-Transfer-Encoding: 7bit
 >
 >  Index: t_ra.sh
 >  ===================================================================
 >  RCS file: /cvsroot/src/tests/net/ndp/t_ra.sh,v
 >  retrieving revision 1.29
 >  diff -p -u -2 -r1.29 t_ra.sh
 >  --- t_ra.sh    22 Jun 2017 09:56:48 -0000      1.29
 >  +++ t_ra.sh    5 Nov 2017 14:46:30 -0000
 >  @@ -288,4 +288,8 @@ ra_flush_prefix_entries_cleanup()
 >   {
 >
 >  +      if [ -f ${PIDFILE} ]; then
 >  +              kill -TERM `cat ${PIDFILE}`
 >  +              wait_term ${PIDFILE}
 >  +      fi
 >         $DEBUG && dump
 >         cleanup
 >  @@ -345,4 +349,8 @@ ra_flush_defrouter_entries_cleanup()
 >   {
 >
 >  +      if [ -f ${PIDFILE} ]; then
 >  +              kill -TERM `cat ${PIDFILE}`
 >  +              wait_term ${PIDFILE}
 >  +      fi
 >         $DEBUG && dump
 >         cleanup
 >  @@ -772,4 +780,8 @@ ra_defrouter_expiration_cleanup()
 >   {
 >
 >  +      if [ -f ${PIDFILE} ]; then
 >  +              kill -TERM `cat ${PIDFILE}`
 >  +              wait_term ${PIDFILE}
 >  +      fi
 >         $DEBUG && dump
 >         cleanup
 >  @@ -837,4 +849,8 @@ ra_prefix_expiration_cleanup()
 >   {
 >
 >  +      if [ -f ${PIDFILE} ]; then
 >  +              kill -TERM `cat ${PIDFILE}`
 >  +              wait_term ${PIDFILE}
 >  +      fi
 >         $DEBUG && dump
 >         cleanup
 >
 >  --Apple-Mail=_D998CD31-DB37-4159-9C9D-F768E4B92A7D--
 >

From: "Ryota Ozaki" <ozaki-r@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/52701 CVS commit: src/tests/net/ndp
Date: Tue, 7 Nov 2017 02:19:23 +0000

 Module Name:	src
 Committed By:	ozaki-r
 Date:		Tue Nov  7 02:19:23 UTC 2017

 Modified Files:
 	src/tests/net/ndp: t_ra.sh

 Log Message:
 Let rtadvd not use syslog for logging

 Thanks to christos@ now rtadvd can log via stderr instead of syslog
 by -D option.

 Address PR bin/52701


 To generate a diff of this commit:
 cvs rdiff -u -r1.30 -r1.31 src/tests/net/ndp/t_ra.sh

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

From: "Martin Husemann" <martin@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/52701 CVS commit: [netbsd-8] src
Date: Tue, 21 Nov 2017 10:54:19 +0000

 Module Name:	src
 Committed By:	martin
 Date:		Tue Nov 21 10:54:19 UTC 2017

 Modified Files:
 	src/tests/net/ndp [netbsd-8]: t_ra.sh
 	src/usr.sbin/rtadvd [netbsd-8]: advcap.c config.c dump.c if.c rrenum.c
 	    rtadvd.8 rtadvd.c timer.c
 Added Files:
 	src/usr.sbin/rtadvd [netbsd-8]: logit.h

 Log Message:
 Pull up following revision(s) (requested by ozaki-r in ticket #358):
 	usr.sbin/rtadvd/rtadvd.c: revision 1.54-1.58
 	usr.sbin/rtadvd/config.c: revision 1.37
 	usr.sbin/rtadvd/if.c: revision 1.25
 	usr.sbin/rtadvd/dump.c: revision 1.15
 	usr.sbin/rtadvd/rrenum.c: revision 1.20
 	usr.sbin/rtadvd/logit.h: revision 1.1
 	usr.sbin/rtadvd/rtadvd.8: revision 1.26
 	tests/net/ndp/t_ra.sh: revision 1.30
 	usr.sbin/rtadvd/timer.c: revision 1.14
 	tests/net/ndp/t_ra.sh: revision 1.31
 	usr.sbin/rtadvd/advcap.c: revision 1.17

 KNF, fix time printing formats.

 Don't start another copy of rtadvd if one is running.

 PR/52618: Shinichi Doyashiki: Don't exit if adding interface to multicast
 group fails. This happens with empty vlan interfaces
 - make syscalls checks against -1
 - fix errors to print %s: instead of <%s>
 XXX: if_vlan is the only pseudo interface in net/ that returns such an
 error..

 Kill rtadvd surely even if the tests fail in the middle
 It may help PR bin/52701.

 Change the meaning of the D flag to print errors to stderr instead of
 syslog(3) and exit if poll(2) fails (intended to be used with unit-tests).

 Mark expandm as preserving format strings.

 Let rtadvd not use syslog for logging
 Thanks to christos@ now rtadvd can log via stderr instead of syslog
 by -D option.
 Address PR bin/52701


 To generate a diff of this commit:
 cvs rdiff -u -r1.27.2.1 -r1.27.2.2 src/tests/net/ndp/t_ra.sh
 cvs rdiff -u -r1.16 -r1.16.8.1 src/usr.sbin/rtadvd/advcap.c
 cvs rdiff -u -r1.36 -r1.36.4.1 src/usr.sbin/rtadvd/config.c
 cvs rdiff -u -r1.14 -r1.14.8.1 src/usr.sbin/rtadvd/dump.c
 cvs rdiff -u -r1.24 -r1.24.8.1 src/usr.sbin/rtadvd/if.c
 cvs rdiff -u -r0 -r1.1.2.2 src/usr.sbin/rtadvd/logit.h
 cvs rdiff -u -r1.19 -r1.19.8.1 src/usr.sbin/rtadvd/rrenum.c
 cvs rdiff -u -r1.25 -r1.25.6.1 src/usr.sbin/rtadvd/rtadvd.8
 cvs rdiff -u -r1.53 -r1.53.4.1 src/usr.sbin/rtadvd/rtadvd.c
 cvs rdiff -u -r1.13 -r1.13.8.1 src/usr.sbin/rtadvd/timer.c

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

State-Changed-From-To: open->feedback
State-Changed-By: ozaki-r@NetBSD.org
State-Changed-When: Wed, 22 Nov 2017 02:03:59 +0000
State-Changed-Why:
Fixed in -current and -8. Let me know if the issue still happens.


From: Andreas Gustafsson <gson@gson.org>
To: gnats-bugs@NetBSD.org
Cc: ozaki-r@NetBSD.org
Subject: Re: bin/52701 (rtadvd logs thousands of syslog messages)
Date: Sat, 20 Jan 2018 23:11:56 +0200

 On Nov 22, 2017, ozaki-r@NetBSD.org wrote:
 > Fixed in -current and -8. Let me know if the issue still happens.

 I can confirm that the syslog messages no longer occur.

 However, since the volume of messages suggests that rtadvd got into
 some kind of busy-loop, and the fixes involved redirecting log
 messages away from syslog and killing rtadvd at the end of the tests,
 I wonder if the underlying issue of rtadvd getting into the loop in
 the first place was addressed, or only hidden by redirecting the
 messages and/or killing the process.
 -- 
 Andreas Gustafsson, gson@gson.org

State-Changed-From-To: feedback->open
State-Changed-By: gson@NetBSD.org
State-Changed-When: Thu, 08 Feb 2018 08:38:53 +0000
State-Changed-Why:
Feedback provided.


>Unformatted:

NetBSD Home
NetBSD PR Database Search

(Contact us) $NetBSD: query-full-pr,v 1.43 2018/01/16 07:36:43 maya Exp $
$NetBSD: gnats_config.sh,v 1.9 2014/08/02 14:16:04 spz Exp $
Copyright © 1994-2017 The NetBSD Foundation, Inc. ALL RIGHTS RESERVED.