NetBSD Problem Report #54706

From george@galis.org  Mon Nov 18 05:09:23 2019
From: root@galis.org
Reply-To: george@galis.org
To: gnats-bugs@NetBSD.org
Subject: ln consuming inodes on wrong device....
X-Send-Pr-Version: 3.95

>Number:         54706
>Category:       kern
>Synopsis:       ln consuming inodes on wrong device....
>Confidential:   no
>Severity:       serious
>Priority:       high
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   unknown
>Arrival-Date:   Mon Nov 18 06:23:01 +0000 2019
>Last-Modified:  Mon Nov 18 16:55:01 +0000 2019
>Originator:     Charlie Root
>Release:        NetBSD 8.1
>Organization:
>Environment:
System: NetBSD adam 8.1 NetBSD 8.1 (GENERIC) #0: Fri May 31 08:43:59 UTC 2019 mkrepro@mkrepro.NetBSD.org:/usr/src/sys/arch/amd64/compile/GENERIC amd64
Architecture: x86_64
Machine: amd64
>Description:

    Very unusual behavior, presumed kernel bug due to circumstance,
in which case I expect the issue will be "untraceable" after reboot.
    While configuring rrdtool based resource monitoring, it became
necessary to "mount -u -orw /dev/wd0a" so that "chmod 701 /HDS5C30"
could be executed. (/dev/sd0a is the root partition) Immediately after
the chmod command, "mount -u -oro /dev/wd0a" was executed, which
corresponds to the fstab config.
    A cron was setup up update rrd databases every minute, and
generate png files every 8 minutes, in a /HDS5C30 submount.
Simultaneously a script was created to fork several times, consume 
a large number of inodes by creating hardlinks to a small tmp file,
then sleep for 2800 seconds and loop. The task is balanced to generate
a load of ~18 for about 2 minutes.
    The hardlink tmp files _are_ being created in in the wd0a tmp dir

find /HDS5C30/tmp/test/ -type f | wc -l
 6968626

however rrdtool graphics (per df -i) are showing inodes consumed on sd0f (/var),
which should have no files related to the rrdtool testing or reporting.

df -ih /dev/sd0f /dev/wd0a
Filesystem         Size       Used      Avail %Cap    iUsed   iAvail %iCap Mounted on
/dev/sd0f          8.7G       495M       7.8G   5%   149683   995915   13% /var
/dev/wd0a          2.0G       305M       1.6G  16%     7439   249071    2% /HDS5C30

the 249071 figure was is noted approx the "same" as yesterday at the beginning
of tmp inode creation, and it doesn't correspond to the above find command results
(same partition).

The first thing I did when I noticed the inodes being used up in /var
was identify the files in question...

The files in sd0f all have the same name pattern, they are small binary data

-rw-r--r--  1 root  wheel  112 Nov 13 15:34 /var/cache/fontconfig/000061f5-c7b4-4c81-aec2-660429f1c736-le64.cache-7

strings /var/cache/fontconfig/000061f5-c7b4-4c81-aec2-660429f1c736-le64.cache-7
/usr/X11R7/lib/X11/fonts/CID

additionally, the file timestams in /var/cache/fontconfig correspond to the inode generation
test interval, and _not_ to any rrdtool png creation 

for a in $( seq 10 120 ) ; do  m=" -mmin +$a -mmin -$((a+1))" ; echo -n "$m " ; find /var/cache/fontconfig $m | wc -l ; done

 -mmin +10 -mmin -11        1
 -mmin +11 -mmin -12       69
 -mmin +12 -mmin -13       51
 -mmin +13 -mmin -14       89
 -mmin +14 -mmin -15      108
 -mmin +15 -mmin -16       95
 -mmin +16 -mmin -17        0
 -mmin +17 -mmin -18        0
 -mmin +18 -mmin -19        0
 -mmin +19 -mmin -20        0
 -mmin +20 -mmin -21        0
 -mmin +21 -mmin -22        0
 -mmin +22 -mmin -23       72
 -mmin +23 -mmin -24      113
 -mmin +24 -mmin -25      120
 -mmin +25 -mmin -26      128
 -mmin +26 -mmin -27       50
 -mmin +27 -mmin -28       68
 -mmin +28 -mmin -29      109
 -mmin +29 -mmin -30      121
 -mmin +30 -mmin -31      125
 -mmin +31 -mmin -32       36
 -mmin +32 -mmin -33        0
 -mmin +33 -mmin -34        0
 -mmin +34 -mmin -35        0
 -mmin +35 -mmin -36        0
 -mmin +36 -mmin -37       39
 -mmin +37 -mmin -38      124
 -mmin +38 -mmin -39      126
 -mmin +39 -mmin -40      112

In order to run that file count in a timely manner, I had to first remove
a substantial number of the /var/cache/fontconfig/ files

find /var/cache/fontconfig/ -mtime +1 -delete

While the wd0a inode use is not showing in df, their creation time also
corresponds to the inode generation test interval, which will be too
time consuming at the moment, and removing the old ones will take some time...

find /HDS5C30/tmp/test -mtime +1 -delete &

however I observe that the inode count is going down on sd0f now that I'm
deleting the older files on wd0a (sorry).

df -hi

Filesystem         Size       Used      Avail %Cap    iUsed   iAvail %iCap Mounted on
/dev/sd0a          2.0G       127M       1.7G   6%     7434   250612    2% /
/dev/sd0f          8.7G       486M       7.8G   5%   145387  1000211   12% /var
/dev/sd0e           17G       2.1G        14G  13%    52379  2199267    2% /usr
tmpfs               64M        12K        64M   0%       32    65507    0% /tmp
kernfs             1.0K       1.0K         0B 100%        0        0    0% /kern
ptyfs              1.0K       1.0K         0B 100%        0        0    0% /dev/pts
procfs             4.0K       4.0K         0B 100%       58      986    5% /proc
tmpfs              256M         0B       256M   0%        1   261713    0% /var/shm
/dev/wd0a          2.0G       167M       1.7G   8%     6999   249511    2% /HDS5C30
/dev/wd0e          2.0T       922G       986G  48%  1325087 130552031    1% /HDS5C30/usr
/dev/wd0f          4.7G       730M       3.8G  15%     2981   618841    0% /HDS5C30/var

I suspect this is a kernel filesystem bug because a large number of (same) file
hardlinks are not indicated in "df -i wd0a" after their creation, while an
unexpected set of files are appearing in /var/cache/fontconfig/

The /var/cache/fontconfig/ files appear all unique, not linked to each other.

pwd ; ls | head -n30 | while read a ; do stat -f '%l %i %z %m %N' "$a" ; done
/var/cache/fontconfig
1 512693 112 1573688066 000061f5-c7b4-4c81-aec2-660429f1c736-le64.cache-7
1 920919 112 1573655868 00009208-b383-47c8-96da-8cffa6d2e132-le64.cache-7
1 928659 112 1573665007 0000c508-4eec-4e49-a67e-178c2582053c-le64.cache-7
1 560010 120 1573634873 00013090-7499-4629-afd1-e161ef40682b-le64.cache-7
1 526409 112 1573704605 00018958-e820-4e78-84b0-70d5d6da78a6-le64.cache-7
1 273234 112 1573731180 0001d879-c1b6-4a4e-83eb-1bf64fa782b3-le64.cache-7
1 378513 120 1573609330 0002edba-186c-4c73-ae4e-ec83892d4fe5-le64.cache-7
1 270530 120 1573727738 0002fa71-3a30-4e47-9256-adc7b792732e-le64.cache-7
1 566580 112 1573642742 00049b78-2ef3-46a3-81e0-260fe7b1f8ce-le64.cache-7
1 254334 112 1573710352 0004e777-ebe7-42e5-80fb-1b4cc63ef3d4-le64.cache-7
1 522770 112 1573700370 00055eeb-8f59-4570-bb89-792157fa6e44-le64.cache-7
1 518414 112 1573695220 0005fa97-07ef-4902-a98c-dd6f8bdc63b0-le64.cache-7
1 551456 120 1573624249 00061df8-64cb-4ebd-97a2-995d5e02990e-le64.cache-7
1 262574 120 1573718330 00062891-df59-49a2-b283-42371402bb9e-le64.cache-7
1 563942 112 1573639372 00065798-484c-46be-af47-2af50a95670d-le64.cache-7
1 525638 112 1573703884 00068cad-4200-4924-9d11-47c735cac6b0-le64.cache-7
1 266147 128 1573722569 0008a475-f031-4b4f-9398-98e64b1dd398-le64.cache-7
1 555174 128 1573628650 0009fceb-f8d8-4c3e-ad1d-f780d19a4f78-le64.cache-7
1 385649 112 1573617710 000b3e03-a696-4efd-b292-5f0705612f02-le64.cache-7
1 525581 112 1573703853 000d824e-4ee9-4d84-8325-4dda075ed45e-le64.cache-7
1 370579 128 1573599721 000d8506-c4c8-406c-9b8b-660539579f85-le64.cache-7
1 378180 128 1573608880 000dfae3-da22-48d5-adbe-83c4bb72e1bc-le64.cache-7
1 269863 112 1573727106 000e24ff-e0fd-48ae-9b48-296748d3f7d0-le64.cache-7
1 934896 112 1573672273 000eb432-470a-408b-8dda-46ec166b696c-le64.cache-7
1 520286 112 1573697372 000ed1d3-eccc-4962-ad9f-e7ae588844ef-le64.cache-7
1 381280 112 1573612839 000edde3-6b00-41fe-979c-c7fd262f4cd7-le64.cache-7
1 523028 112 1573700533 000f0205-0036-4eaa-b79d-742a56145e86-le64.cache-7
1 271221 112 1573728636 000f51f2-5667-446f-a3ff-64b9101e7256-le64.cache-7
1 566440 120 1573642679 000f55cd-a266-4fdd-b6f3-e0af8127b22d-le64.cache-7
1 918304 128 1573652803 000f6d10-b7b5-4664-906a-d6c2bb5bc09d-le64.cache-7

Not sure if this is a rrdtool bug

pkgin
rrdtool-1.7.2nb1 
http://nyftp.netbsd.org/pub/pkgsrc/packages/NetBSD/amd64/8.1/All

or kernel related. The fontconfig files creation and df inode output
are both suspect.

    I suspect a kernel mounted device pointer would be properly reset on
reboot, (unless it is a pkg issue), so I've avoided rebooting, and will
avoid recycling to facilitate debug, unless something else comes up.

uhub0 at usb0: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhub1 at usb1: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
uhub2 at usb2: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
uhub3 at usb3: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub3: 2 ports with 2 removable, self powered
uhub4 at usb4: vendor 8086 (0x8086) EHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 1
uhub4: 8 ports with 8 removable, self powered
umass0 at uhub4 port 1 configuration 1 interface 0
umass0: Generic (0x5e3) USB Storage (0x736), rev 2.00/2.72, addr 2
umass0: using SCSI over Bulk-Only
scsibus0 at umass0: 2 targets, 1 lun per target
sd0 at scsibus0 target 0 lun 0: <Generic, STORAGE DEVICE, 0272> disk removable
sd0: fabricating a geometry
sd0: 30436 MB, 30436 cyl, 64 head, 32 sec, 512 bytes/sect x 62333952 sectors
sd0: fabricating a geometry
wd0 at atabus2 drive 0
wd0: <Hitachi HDS5C3030ALA630>
wd0: drive supports 16-sector PIO transfers, LBA48 addressing
wd0: 2794 GB, 5814021 cyl, 16 head, 63 sec, 512 bytes/sect x 5860533168 sectors
wd0: 32-bit data port
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133)
wd0(piixide1:0:0): using PIO mode 4, Ultra-DMA mode 6 (Ultra/133) (using DMA)


>How-To-Repeat:

    Not sure, this issue was triggered while a sub mount of wd0a
was in active read write use, while and simultaneously remounting
the partition from ro to rw, in order to change the mount point
mode from 700 to 701, and then remounted to ro.
    Then a large number of inodes were created per small file
on the remounted partition. Simultaneously 70 rrdtool db are updated
every minute and generating png graphs every 8 minute (all to /HDS5C30/usr).

>Fix:

>Audit-Trail:
From: mlelstv@serpens.de (Michael van Elst)
To: gnats-bugs@netbsd.org
Cc: 
Subject: Re: kern/54706: ln consuming inodes on wrong device....
Date: Mon, 18 Nov 2019 08:46:36 -0000 (UTC)

 root@galis.org writes:

 >    The hardlink tmp files _are_ being created in in the wd0a tmp dir

 >find /HDS5C30/tmp/test/ -type f | wc -l
 > 6968626

 >however rrdtool graphics (per df -i) are showing inodes consumed on sd0f (/var),
 >which should have no files related to the rrdtool testing or reporting.

 Hardlinks don't consume inodes. It's just directory entries pointing to
 the same inode.



 >df -ih /dev/sd0f /dev/wd0a
 >Filesystem         Size       Used      Avail %Cap    iUsed   iAvail %iCap Mounted on
 >/dev/sd0f          8.7G       495M       7.8G   5%   149683   995915   13% /var
 >/dev/wd0a          2.0G       305M       1.6G  16%     7439   249071    2% /HDS5C30

 You seem to have lots of files on /var. Can you find out what they are?
 fontconfig can have lots of cache files, but usually only a few thousand,
 not 140000. My guess would be lots of files in /var/tmp generated by
 rrdtool.


 -- 
 -- 
                                 Michael van Elst
 Internet: mlelstv@serpens.de
                                 "A potential Snark may lurk in every tree."

From: George Georgalis <george@galis.org>
To: gnats-bugs@netbsd.org
Cc: kern-bug-people@netbsd.org, gnats-admin@netbsd.org, netbsd-bugs@netbsd.org
Subject: Re: kern/54706: ln consuming inodes on wrong device....
Date: Mon, 18 Nov 2019 08:54:15 -0800

 On Mon, Nov 18, 2019 at 1:30 AM Michael van Elst <mlelstv@serpens.de> wrote:
 >
 >  Hardlinks don't consume inodes. It's just directory entries pointing to
 >  the same inode.

 Oh, well that is good to know. I'll be able to use them up a lot
 quicker next time.

 >  >df -ih /dev/sd0f /dev/wd0a
 >  >Filesystem         Size       Used      Avail %Cap    iUsed   iAvail %iCap Mounted on
 >  >/dev/sd0f          8.7G       495M       7.8G   5%   149683   995915   13% /var
 >  >/dev/wd0a          2.0G       305M       1.6G  16%     7439   249071    2% /HDS5C30
 >
 >  You seem to have lots of files on /var. Can you find out what they are?
 >  fontconfig can have lots of cache files, but usually only a few thousand,
 >  not 140000. My guess would be lots of files in /var/tmp generated by
 >  rrdtool.

 Yes, I have confirmed tons of fontconfig files, about 6 per rrdtool db table.
 Given 63 separate metric tables, and 388 new fontconfig cache files per graph
 rendering, invoked from cron every 8 minutes. That explains the inode
 consumption.

 I'll open a separate PR for rrd tool. This one can be closed. Thank you!

 -George



 --
 George Georgalis, (415) 894-2710, http://www.galis.org/

Home	PR Database Search