NetBSD Problem Report #54488

From gson@gson.org  Mon Aug 26 08:38:38 2019
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 9F39F7A14B
	for <gnats-bugs@gnats.NetBSD.org>; Mon, 26 Aug 2019 08:38:38 +0000 (UTC)
Message-Id: <20190826083835.4FB73989382@guava.gson.org>
Date: Mon, 26 Aug 2019 11:38:35 +0300 (EEST)
From: gson@gson.org (Andreas Gustafsson)
Reply-To: gson@gson.org (Andreas Gustafsson)
To: gnats-bugs@NetBSD.org
Subject: LFS tests log errors since 2019-08-22
X-Send-Pr-Version: 3.95

>Number:         54488
>Category:       bin
>Synopsis:       LFS tests log errors since 2019-08-22
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    brad
>State:          closed
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Mon Aug 26 08:40:00 +0000 2019
>Closed-Date:    Sun Sep 01 13:40:57 +0000 2019
>Last-Modified:  Sun Sep 01 13:40:57 +0000 2019
>Originator:     Andreas Gustafsson
>Release:        NetBSD-current, source date >= 2019.08.22.20.28.08
>Organization:

>Environment:
System: NetBSD
Architecture: x86_64
Machine: amd64
>Description:

Running the ATF tests now causes a lot of LFS releated error messages
to be logged, for example:

      lfs_extendfile: Aug 23 15:18:40  lfs_cleanerd[22597]: couldn't convert '/dev/device0.lfs' ro raw name: No such file or directory
  Aug 23 15:18:40	 lfs_cleanerd[22597]: /mnt: couldn't init: error code -1
  [4.201046s] Passed.
      lfs_extendfile_append: Aug 23 15:18:44  lfs_cleanerd[20748]: couldn't convert '/dev/device0.lfs' ro raw name: No such file or directory
  Aug 23 15:18:44	 lfs_cleanerd[20748]: /mnt: couldn't init: error code -1
  [4.022019s] Passed.
      lfs_holywrite: Aug 23 15:18:48  lfs_cleanerd[21480]: couldn't convert '/dev/device0.lfs' ro raw name: No such file or directory
  Aug 23 15:18:48	 lfs_cleanerd[21480]: /mnt: couldn't init: error code -1
  [3.524514s] Passed.

This started with the following commits:

  2019.08.22.20.23.43 brad src/lib/libutil/getdiskrawname.c 1.6
  2019.08.22.20.26.07 brad src/sbin/resize_lfs/resize_lfs.c 1.15
  2019.08.22.20.28.08 brad src/libexec/lfs_cleanerd/lfs_cleanerd.c 1.59

The tests are passing despite the error messages.

Also, I'm guessing the "ro" should be "to".

>How-To-Repeat:

Run the ATF tests.

>Fix:

>Release-Note:

>Audit-Trail:

Responsible-Changed-From-To: bin-bug-people->brad
Responsible-Changed-By: gson@NetBSD.org
Responsible-Changed-When: Mon, 26 Aug 2019 08:41:39 +0000
Responsible-Changed-Why:
Over to committer.


From: Brad Spencer <brad@anduin.eldar.org>
To: gnats-bugs@netbsd.org
Cc: brad@netbsd.org, gnats-admin@netbsd.org, netbsd-bugs@netbsd.org,
        gson@NetBSD.org, gson@gson.org
Subject: Re: bin/54488 (LFS tests log errors since 2019-08-22)
Date: Mon, 26 Aug 2019 16:43:08 -0400

 gson@NetBSD.org writes:

 > Synopsis: LFS tests log errors since 2019-08-22
 >
 > Responsible-Changed-From-To: bin-bug-people->brad
 > Responsible-Changed-By: gson@NetBSD.org
 > Responsible-Changed-When: Mon, 26 Aug 2019 08:41:39 +0000
 > Responsible-Changed-Why:
 > Over to committer.


 I am investigating...  there may be a rumpism..  the atf test case for
 LFS is also a bit unusual... it compiles and links into itself the
 cleaner.


 The usual cases work fine (test3 is a 9.99.10 DOMU from 2019-08-24):

 test3# vnconfig vnd0 /var/tmp/dk.img
 test3# disklabel -e vnd0a
 test3# newfs_lfs vnd0a
 Creating a version 2 LFS32 with roll-forward ident 0x5458c880
 99.0MB in 99 segments of size 1048576
 super-block backups (for fsck -b #) at:
 16, 18432, 36864, 55296, 73728, 92160, 110592, 129024, 147456, 165888.
 test3# mount -t lfs /dev/vnd0a /mnt
 test3# df -t lfs
 Filesystem    1K-blocks       Used      Avail %Cap Mounted on
 /dev/vnd0a        80785          8      72697   0% /mnt
 test3# ps -auxww|grep lfs
 root    1637  0.0  0.0 22404  1692 ?       Ss    4:22PM 0:00.00 /libexec/lfs_cleanerd -b -n 4 /mnt 
 root     648  0.0  0.0 17944  1576 pts/0   S+    4:22PM 0:00.00 grep lfs 

 test3# zfs create -V 100m tank/lfstest
 test3# newfs_lfs -F /dev/zvol/rdsk/tank/lfstest
 Creating a version 2 LFS32 with roll-forward ident 0x721616f9
 99.0MB in 99 segments of size 1048576
 super-block backups (for fsck -b #) at:
 16, 18432, 36864, 55296, 73728, 92160, 110592, 129024, 147456, 165888.
 test3# mount -t lfs /dev/zvol/dsk/tank/lfstest /mnt
 test3# df -t lfs
 Filesystem                  1K-blocks       Used      Avail %Cap Mounted on
 /dev/zvol/dsk/tank/lfstest      80785          8      72697   0% /mnt
 test3# ps -auxww|grep lfs
 root    1492  0.0  0.0 25452  1688 ?       Ss    4:28PM 0:00.00 /libexec/lfs_cleanerd -b -n 4 /mnt 
 root     905  0.0  0.0 19400  1580 pts/0   S+    4:28PM 0:00.00 grep lfs 

 test3# disklabel -e xbd3
 test3# newfs_lfs /dev/rxbd3a
 Creating a version 2 LFS32 with roll-forward ident 0x110f9ec5
 1999.0MB in 1999 segments of size 1048576
 super-block backups (for fsck -b #) at:
 16, 407552, 815104, 1222656, 1630208, 2037760, 2445312, 2852864, 3260416, 
 3667968.
 test3# mount -t lfs /dev/xbd3a /mnt
 test3# df -t lfs
 Filesystem    1K-blocks       Used      Avail %Cap Mounted on
 /dev/xbd3a      1843049          8    1658730   0% /mnt
 test3# ps -auxww|grep lfs
 root    1432  0.0  0.0 22408  1772 ?       Ss    4:29PM 0:00.00 /libexec/lfs_cleanerd -b -n 4 /mnt 
 root    1557  0.0  0.0 19368  1572 pts/0   S+    4:29PM 0:00.00 grep lfs 


 There is a problem with rump, but I am not sure I broke that:

 test3# mount -o rump -t lfs /dev/xbd3a /mnt
 rump_lfs: rump_lfs: puffs_daemonmount: Device busy
 : Device busy

 Oddly, it almost works with the raw device:

 test3# mount -o rump -t lfs /dev/rxbd3a /mnt
 [   1.0300090] WARNING: the log-structured file system is experimental
 [   1.0300090] WARNING: it may cause system crashes and/or corrupt data
 test3# lfs_cleanerd[1621]: couldn't convert '/dev/rxbd3a' ro raw name: Inappropriate file type or format
 lfs_cleanerd[1621]: /mnt: couldn't init: error code -1
 lfs_cleanerd[1621]: : detaching cleaner


 This one may be my fault, if lfs_cleanerd needs to work on files.  I
 will test that (and the above with the raw device):

 test3# mount -o rump -t lfs /var/tmp/dk.img /mnt
 [   1.0300090] WARNING: the log-structured file system is experimental
 [   1.0300090] WARNING: it may cause system crashes and/or corrupt data
 test3# lfs_cleanerd[1444]: couldn't convert '/var/tmp/dk.img' ro raw name: Inappropriate file type or format
 lfs_cleanerd[1444]: /mnt: couldn't init: error code -1
 lfs_cleanerd[1444]: : detaching cleaner

 However, something else may be very wrong:

 test3# df
 Filesystem       1K-blocks       Used      Avail %Cap Mounted on
 /dev/xbd0a        10079822    2069410    7506422  21% /
 rstuff/var          409600     267402     142198  65% /var
 tmpfs              1048576          4    1048572   0% /var/shm
 tmpfs              1048576          4    1048572   0% /tmp
 kernfs                   1          1          0 100% /kern
 ptyfs                    1          1          0 100% /dev/pts
 procfs                   4          4          0 100% /proc
 rstuff             1630548         23    1630525   0% /rstuff
 /var/tmp/dk.img      80777          8      72689   0% /mnt
 test3# df -t lfs
 test3# ls -l /mnt
 test3# touch /mnt/A
 [ 104.7700090] panic: kernel diagnostic assertion "*vpp == NULL" failed: file "/usr/src/sys/rump/fs/lib/liblfs/../../../../ufs/lfs/lfs_vnops.c", line 879 
 [ 104.7700090] rump kernel halting...
 halted
 touch: /mnt/A: Device not configured



 LFS will more or less work just fine a lot of the time without the
 cleaner running, at least in my experience.

State-Changed-From-To: open->feedback
State-Changed-By: brad@NetBSD.org
State-Changed-When: Fri, 30 Aug 2019 23:53:32 +0000
State-Changed-Why:
Commited fixes that are believe to have dealt with the problem.


State-Changed-From-To: feedback->closed
State-Changed-By: gson@NetBSD.org
State-Changed-When: Sun, 01 Sep 2019 13:40:57 +0000
State-Changed-Why:
The messages are gone as of source date 2019.08.30.23.45.13.  Thanks.


>Unformatted:

Home	PR Database Search