[SERVER-7725] File allocation leads to full disk, e4fs allocation error Created: 20/Nov/12  Updated: 08/Mar/13  Resolved: 24/Feb/13

Status: Closed
Project: Core Server
Component/s: Stability
Affects Version/s: 2.0.6
Fix Version/s: None

Type: Bug Priority: Critical - P2
Reporter: Benjamin Abbott-Scott Assignee: David Hows
Resolution: Incomplete Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

uname: Linux 421762-mongo3.enl.enphaseenergy.com 2.6.18-238.45.1.el5 #1 SMP Thu Sep 20 12:19:35 EDT 2012 x86_64 x86_64 x86_64 GNU/Linux
e4fsprogs version 1.41.12-2.el5
mongo version mongo-10gen-server-2.0.6-mongodb_1.x86_64
Hardware: Dell PowerEdge 2970, PowerEdge R710


Attachments: Text File dmesg.txt     Text File dmesg.txt     Text File mongod.log    
Operating System: ALL
Steps To Reproduce:

Unable to reproduce intentionally

Participants:

 Description   

On November 3, mongo1, a hidden member of the replica set had mongod go unresponsive. Examining system logs, we found thousands of messages like:

Nov 3 17:20:47 276036-mongo1 kernel: EXT4-fs: Can't allocate: Allocation context details:
Nov 3 17:20:47 276036-mongo1 kernel: EXT4-fs: status 1 flags 3104
Nov 3 17:20:47 276036-mongo1 kernel: EXT4-fs: orig 1598/525/1@477864, goal 1598/515/2048@477184, best 0/0/0@477864 cr 3
Nov 3 17:20:47 276036-mongo1 kernel: EXT4-fs: 0 scanned, 0 found

The only EXT4 filesystem on the server is the mongo partition, and mongod is the sole process using it. The only correllating event we could find in mongo logs was:

Sat Nov 3 17:18:48 [FileAllocator] allocating new datafile /var/lib/mongo/enlighten_production/enlighten_production.93, filling with zeroes...

On other FileAllocator events, an ‘allocation complete’ message was logged as well. This one had no matching completion message. Eventually mongod failed:

Sat Nov 3 17:25:41 [journal] LogFile::synchronousAppend failed with 139264 bytes unwritten out of 139264 bytes; b=0x2adec2402000 errno:28 No space left on device
Sat Nov 3 17:25:41 Got signal: 6 (Aborted).

Sat Nov 3 17:25:41 Backtrace:
0xa95ce9 0x3f322302d0 0x3f32230265 0x3f32231d10 0x75c13d 0x777da5 0x777fde 0x762f1c 0x76376d 0x763a8d 0x76436b 0xaabca0 0x3f3360673d 0x3f322d44bd
/usr/bin/mongod(_ZN5mongo10abruptQuitEi+0x3a9) [0xa95ce9]
/lib64/libc.so.6 [0x3f322302d0]
/lib64/libc.so.6(gsignal+0x35) [0x3f32230265]
/lib64/libc.so.6(abort+0x110) [0x3f32231d10]
/usr/bin/mongod(_ZN5mongo7LogFile17synchronousAppendEPKvm+0x12d) [0x75c13d]
/usr/bin/mongod(_ZN5mongo3dur7Journal7journalERKNS0_11JSectHeaderERKNS_14AlignedBuilderE+0x1e5) [0x777da5]
/usr/bin/mongod(_ZN5mongo3dur14WRITETOJOURNALENS0_11JSectHeaderERNS_14AlignedBuilderE+0x4e) [0x777fde]
/usr/bin/mongod(_ZN5mongo3dur28_groupCommitWithLimitedLocksEv+0x24c) [0x762f1c]
/usr/bin/mongod(_ZN5mongo3dur27groupCommitWithLimitedLocksEv+0x1d) [0x76376d]
/usr/bin/mongod [0x763a8d]
/usr/bin/mongod(_ZN5mongo3dur9durThreadEv+0x10b) [0x76436b]
/usr/bin/mongod(thread_proxy+0x80) [0xaabca0]
/lib64/libpthread.so.0 [0x3f3360673d]
/lib64/libc.so.6(clone+0x6d) [0x3f322d44bd]
Sat Nov 3 17:25:41 Invalid access at address: 0
Sat Nov 3 17:25:41 Got signal: 11 (Segmentation fault).

The server was rebooted, and mongo was able to recover itself as secondary. Three days later, the primary server in the set, mongo3 (syslog still had the hostname as cache2), had the same issue:

Nov 6 10:44:46 421762-cache2 kernel: EXT4-fs: Can't allocate: Allocation context details:
Nov 6 10:44:46 421762-cache2 kernel: EXT4-fs: status 1 flags 3104
Nov 6 10:44:46 421762-cache2 kernel: EXT4-fs: orig 1597/1831/64@300060, goal 1597/1830/2048@299008, best 0/0/0@300060 cr 3
Nov 6 10:44:46 421762-cache2 kernel: EXT4-fs: 0 scanned, 0 found

Tue Nov 6 10:44:29 [FileAllocator] allocating new datafile /var/lib/mongo/enlighten_production/enlighten_production.94, filling with zeroes...
...
Tue Nov 6 10:46:11 [journal] LogFile::synchronousAppend failed with 114688 bytes unwritten out of 114688 bytes; b=0x2adccb794000 errno:28 No space left on device
Tue Nov 6 10:46:11 Got signal: 6 (Aborted).

In both cases, there was more than 100GB free on the partition at the time. It looks as though the allocation, or the zeroing, went haywire and filled the whole partition.



 Comments   
Comment by David Hows [ 27/Nov/12 ]

Hi Benjamin,

From your dmesg output i can see a couple of things worth noting, but first has the system been rebooted since the issue occurred? And has the issue recurred subsequently?

The devices dm-3 and dm-4 are both running ext4 and appear to be running without journal and are running unchecked. Additionally dm-3 has a mount options which it cannot parse and appears to have failed its barrier check.

EXT4-fs (dm-3): mounted filesystem without journal
EXT4-fs (dm-3): Unrecognized mount option "discard" or missing value
EXT4-fs (dm-3): Unrecognized mount option "discard" or missing value
EXT4-fs (dm-3): mounted filesystem with writeback data mode
JBD: barrier-based sync failed on dm-3-8 - disabling barriers
EXT4-fs (dm-4): warning: mounting unchecked fs, running e2fsck is recommended
EXT4-fs (dm-4): mounted filesystem without journal

Can you run the following command to ID which devices map to which of the vol groups?

lvdisplay|awk  '/LV Name/{n=$3} /Block device/{d=$3; sub(".*:","dm-",d); print d,n;}'

Can you please attach your /etc/fstab file? I would like to see what mount options are being passed to where.

Finally, can you give some background as to why you are running your filesystems in barrier mode and writeback mode?

Cheers,

David

Comment by Benjamin Abbott-Scott [ 27/Nov/12 ]

mongod log minus connection actions (on the order of 4200/min)

Comment by Benjamin Abbott-Scott [ 27/Nov/12 ]

Attaching dmesg output. SMART not available as the drives are presented by the PERC controller, but omsa reports no predicted failures.

bascott@421762-mongo3 20:10 $ df -h
Filesystem Size Used Avail Use% Mounted on
/dev/mapper/201206141135-root
37G 6.4G 29G 19% /
/dev/mapper/201206141135-temp
2.0G 85M 1.8G 5% /tmp
/dev/sda1 244M 27M 205M 12% /boot
tmpfs 24G 0 24G 0% /dev/shm
/dev/mapper/vg2-vg2_mongo
553G 415G 111G 80% /var/lib/mongo
/dev/mapper/vg1-vg1_backups
58G 59M 55G 1% /var/dump/mongo
bascott@421762-mongo3 20:10 $ mount
/dev/mapper/201206141135-root on / type ext3 (rw)
proc on /proc type proc (rw)
sysfs on /sys type sysfs (rw)
devpts on /dev/pts type devpts (rw,gid=5,mode=620)
/dev/mapper/201206141135-temp on /tmp type ext3 (rw,noexec,nosuid,nodev)
/dev/sda1 on /boot type ext3 (rw)
tmpfs on /dev/shm type tmpfs (rw,noexec,nosuid,nodev)
none on /proc/sys/fs/binfmt_misc type binfmt_misc (rw)
sunrpc on /var/lib/nfs/rpc_pipefs type rpc_pipefs (rw)
/dev/mapper/vg2-vg2_mongo on /var/lib/mongo type ext4 (rw,noatime,nodiratime,data=writeback)
/dev/mapper/vg1-vg1_backups on /var/dump/mongo type ext4 (rw)

sudo /usr/sbin/vgdisplay -v vg2
Using volume group(s) on command line
Finding volume group "vg2"
— Volume group —
VG Name vg2
System ID
Format lvm2
Metadata Areas 1
Metadata Sequence No 3
VG Access read/write
VG Status resizable
MAX LV 0
Cur LV 1
Open LV 1
Max PV 0
Cur PV 1
Act PV 1
VG Size 561.57 GB
PE Size 4.00 MB
Total PE 143761
Alloc PE / Size 143761 / 561.57 GB
Free PE / Size 0 / 0
VG UUID zFk7tA-P01a-J5NS-JQzM-5C4n-5cSx-kfjAMz

— Logical volume —
LV Name /dev/vg2/vg2_mongo
VG Name vg2
LV UUID 6giOHJ-ijqj-kqsK-ZZsK-Rw1V-wHeM-MtmvL5
LV Write Access read/write
LV Status available

  1. open 1
    LV Size 561.57 GB
    Current LE 143761
    Segments 1
    Allocation inherit
    Read ahead sectors auto
  • currently set to 256
    Block device 253:3

— Physical volumes —
PV Name /dev/sda5
PV UUID PwYz1m-5NFH-zqJW-e9p6-M37C-nrmK-p8HYQR
PV Status allocatable
Total PE / Free PE 143761 / 0

Comment by David Hows [ 22/Nov/12 ]

Hi Benjamin,

This particular error comes from the Linux kernel itself and is indicative of some form of error working with the ext4 device.

Can you please attach log files mongod instance in question, as I would like to see what it was doing beforehand.

Can you also provide:

  1. The output of df -h. This gives us an idea of your disk layout.
  2. The output of mount. This will show us the mount options used for your fileshare
  3. The full output of dmesg. This is the kernel log, which may have some indicators as to why there were EXT4 issues.
  4. If possible can you provide the output of smartctl -H /dev/XXXX Where /dev/XXXX is the ext4 device mongo is mounted on. This will do a disk health check on a SMART enabled drive.

It may also be worthwhile you're looking to see if RedHat as any information on this issue.

Cheers,

David

Generated at Thu Feb 08 03:15:25 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.