kern/181375: disk free space blackhole magic

Konstantin konstantin.debalyuk at kaspersky.com
Sun Aug 18 14:30:01 UTC 2013


>Number:         181375
>Category:       kern
>Synopsis:       disk free space blackhole magic
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Sun Aug 18 14:30:00 UTC 2013
>Closed-Date:
>Last-Modified:
>Originator:     Konstantin
>Release:        FreeBSD 8.3 - FreeBSD 8.4
>Organization:
Kaspersky Lab
>Environment:
FreeBSD 8.3-RELEASE-p5 FreeBSD 8.3-RELEASE-p5 #1: Thu Dec  6 17:13:30 UTC 2012     root at tb.kaspersky-labs.com:/usr/obj/usr/src/sys/GENERIC  amd64

FreeBSD test 8.4-RELEASE FreeBSD 8.4-RELEASE #0 r251259: Sun Jun  2 21:26:57 UTC 2013     root at bake.isc.freebsd.org:/usr/obj/usr/src/sys/GENERIC  amd64

>Description:
FreeBSD 8.3 - FreeBSD 8.4
amd64
SMP
soft updates
noatime

A daemon running as unprivileged user writes a log. Newsyslog rotates this log every hour and compress it by gzip. Some time later (about 1-2 weeks on our real systems) filesystem gets full. df and du show different results. Kill processes ('/etc/rc.d/jail stop' to be honest) doesn't help. Finally, it is impossible to umount this partition. We get "Device busy" error, but fstat and/or lsof doesn't show something. We know about "open file deletion" issue
and other reasons why df and du shows different results, but it looks like it is not our case. Our real systems use jail environment, but it is possible to repeat this strange behavior without jail. We could not repeat this on non-SMP system, but it is not heavily tested.

Below are more details:

# tunefs -p /dev/mfid0p4
tunefs: POSIX.1e ACLs: (-a)                                disabled
tunefs: NFSv4 ACLs: (-N)                                   disabled
tunefs: MAC multilabel: (-l)                               disabled
tunefs: soft updates: (-n)                                 enabled
tunefs: gjournal: (-J)                                     disabled
tunefs: trim: (-t)                                         disabled
tunefs: maximum blocks per file in a cylinder group: (-e)  2048
tunefs: average file size: (-f)                            16384
tunefs: average number of files in a directory: (-s)       64
tunefs: minimum percentage of free space: (-m)             8%
tunefs: optimization preference: (-o)                      time
tunefs: volume label: (-L)                                 

We tested with disabled Soft Updates. It did not help.

/etc/fstat:

/dev/mfid0p4	/jail	ufs	rw,noatime	2	2

We tested without noatime options. It did not help.

jail newsyslog.conf:

/var/log/urep.txt	kuser:logv	664	24	*	1	Z /var/run/kur.service.pid

real logs:

-rw-rw-r--   1 1001  1002  17361916663 Aug 16 18:59 urep.txt
-rw-rw-r--   1 1001  1002   5801630304 Aug 16 18:00 urep.txt.0.gz
-rw-rw-r--   1 1001  1002   4950129578 Aug 16 17:00 urep.txt.1.gz
-rw-rw-r--   1 1001  1002   2333474330 Aug 16 08:00 urep.txt.10.gz
-rw-rw-r--   1 1001  1002   1154592135 Aug 16 07:00 urep.txt.11.gz
-rw-rw-r--   1 1001  1002    783671738 Aug 16 06:00 urep.txt.12.gz
-rw-rw-r--   1 1001  1002    641988029 Aug 16 05:00 urep.txt.13.gz
-rw-rw-r--   1 1001  1002    711639597 Aug 16 04:00 urep.txt.14.gz
-rw-rw-r--   1 1001  1002    858166595 Aug 16 03:00 urep.txt.15.gz
-rw-rw-r--   1 1001  1002   1129264281 Aug 16 02:00 urep.txt.16.gz
-rw-rw-r--   1 1001  1002   1825284327 Aug 16 01:00 urep.txt.17.gz
-rw-rw-r--   1 1001  1002   2336803342 Aug 16 00:00 urep.txt.18.gz
-rw-rw-r--   1 1001  1002   2412378597 Aug 15 23:00 urep.txt.19.gz
-rw-rw-r--   1 1001  1002   5808607921 Aug 16 16:00 urep.txt.2.gz
-rw-rw-r--   1 1001  1002   2751801103 Aug 15 22:00 urep.txt.20.gz
-rw-rw-r--   1 1001  1002   2546710751 Aug 15 21:00 urep.txt.21.gz
-rw-rw-r--   1 1001  1002   2540838045 Aug 15 20:00 urep.txt.22.gz
-rw-rw-r--   1 1001  1002   3015737372 Aug 15 19:00 urep.txt.23.gz
-rw-rw-r--   1 1001  1002   3251842089 Aug 15 18:00 urep.txt.24.gz
-rw-rw-r--   1 1001  1002   5239690207 Aug 16 15:00 urep.txt.3.gz
-rw-rw-r--   1 1001  1002   6059472499 Aug 16 14:00 urep.txt.4.gz
-rw-rw-r--   1 1001  1002   6249745715 Aug 16 13:00 urep.txt.5.gz
-rw-rw-r--   1 1001  1002   6314110754 Aug 16 12:00 urep.txt.6.gz
-rw-rw-r--   1 1001  1002   6142097019 Aug 16 11:00 urep.txt.7.gz
-rw-rw-r--   1 1001  1002   5700280821 Aug 16 10:00 urep.txt.8.gz
-rw-rw-r--   1 1001  1002   3843021410 Aug 16 09:00 urep.txt.9.gz

# dmesg
pid 81826 (ksn_urlrepd), uid 1001 inumber 15002792 on /jail: filesystem full
pid 81826 (ksn_urlrepd), uid 1001 inumber 15002792 on /jail: filesystem full
pid 81826 (ksn_urlrepd), uid 1001 inumber 15002792 on /jail: filesystem full
pid 81826 (ksn_urlrepd), uid 1001 inumber 15002792 on /jail: filesystem full

# df -h
Filesystem      Size    Used   Avail Capacity  Mounted on
/dev/mfid0p2    9.7G    1.1G    8.0G    12%    /
devfs           1.0k    1.0k      0B   100%    /dev
/dev/mfid0p4    256G    238G   -2.9G   101%    /jail
devfs           1.0k    1.0k      0B   100%    /jail/jail0/dev

du show different free space:

# du -h -d 1 / | grep jail
124G	/jail

Ok, try to stop jail and check free space again.

# /etc/rc.d/jail stop
Stopping jails: k.kaspersky-labs.com.

Nothing has changed. du and df show the same values.

Ok, try to umount filesystem.

# umount /dev/mfid0p4
umount: unmount of /jail failed: Device busy

Are you sure, really?

# sync
# fstat | grep jail

Nobody use /jail!

# umount /dev/mfid0p4
umount: unmount of /jail failed: Device busy

We were trying to sync/fstat/umount several times without success. We were waiting several hours. Nothing has changed.

Ok, finally try to umount -f

# umount -f /dev/mfid0p4

Yeah!

# fsck /dev/mfid0p4
** /dev/mfid0p4
** Last Mounted on /jail
** Phase 1 - Check Blocks and Sizes
** Phase 2 - Check Pathnames
** Phase 3 - Check Connectivity
** Phase 4 - Check Reference Counts
** Phase 5 - Check Cyl groups
25147 files, 65589771 used, 68699872 free (12208 frags, 8585958 blocks, 0.0% fragmentation)

***** FILE SYSTEM IS CLEAN *****

There are no any errors.

Mount it back and check free space.

# mount /dev/mfid0p4
# df -h
Filesystem      Size    Used   Avail Capacity  Mounted on
/dev/mfid0p2    9.7G    1.1G    8.0G    12%    /
devfs           1.0k    1.0k      0B   100%    /dev
/dev/mfid0p4    256G    125G    110G    53%    /jail
# du -h -d 1 / | grep jail
125G	/jail

Yeah!

>How-To-Repeat:
1. Create a fs partition and mount it somewhere. It is better to create small size partition. We will use /data for example. 

2. Add a local unprivileged account. We will use account named 'logv' and the same group name for example. Create some subdirectory in the /data and give it 'rwx' access rights for our account. We will use /data/logv.
 
3. Add to /etc/newsyslog.conf: 

/data/logv/test.log              logv:logv 664     24      *       1       NZ

i.e. rotate log every hour, owner and group for the archive file is our account, no need to send signal, compress log with gzip, keep a 24 gzipped copies.  

4. Start with privilege of logv account simple script:

while [ 1 -ne 0 ] ; do echo 111111111111111111111111 >> /data/logv/test.log; done

Wait from several hours to several days. Waiting time depend on power of the system and the partition size. You can check filesystem free size by 'df -h | grep data' and 'du -h -d 1 / | grep data' commands.  When you see a big difference between du and df free space time has come. Kill the script, comment out rotation of log in the /etc/newsyslog.conf, sync, check by fstat and/or lsof usage of our partition, kill all if need, try to umount the partition.

>Fix:
Not a real fix: 'umount -f'

>Release-Note:
>Audit-Trail:
>Unformatted:


More information about the freebsd-bugs mailing list