Bug 206820 - [ext2fs] Panic when writing to ext3fs mounted as ext2fs
Summary: [ext2fs] Panic when writing to ext3fs mounted as ext2fs
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: 9.3-STABLE
Hardware: Any Any
: --- Affects Only Me
Assignee: Pedro F. Giffuni
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-02-01 14:27 UTC by Arrigo Marchiori
Modified: 2016-02-08 11:48 UTC (History)
1 user (show)

See Also:
pfg: mfc-stable10+
pfg: mfc-stable9+


Attachments
/var/crash/core.txt from the first panic (512.72 KB, text/plain)
2016-02-01 14:31 UTC, Arrigo Marchiori
no flags Details
/var/crash/core.txt from the second panic (476.45 KB, text/plain)
2016-02-01 14:32 UTC, Arrigo Marchiori
no flags Details
Output of dumpe2fs on an ext2 filesystem correctly populated by stable r294970 (18.07 KB, text/plain)
2016-02-03 14:54 UTC, Arrigo Marchiori
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Arrigo Marchiori 2016-02-01 14:27:03 UTC
I encountered two panics on the very same operation: writing files to a ext3fs formatted USB drive that is mounted as ext2fs.

The filesystem is created by a shell script, issuing the following commands:

# mkfs.ext3 /dev/da0s1
# tune2fs -O ^dir_index /dev/da0s1
# mount -t ext2fs /dev/da0s1 /mnt

And files are extracted from a tar archive (produced by gnu tar):

# ssh linuxhost 'cat filesystem.tar.bz2' | tar -C /mnt -xjf -'

My system is a 9-STABLE updated this morning.

# uname -a 
FreeBSD myhost 9.3-STABLE FreeBSD 9.3-STABLE #144 r295117M: Mon Feb  1 09:31:54 CET 2016     root@myhost:/usr/obj/usr/src/sys/GENERIC  i386

Both panics are triggered by function ext2_i2ei at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_inode_cnv.c:152

Here is an excerpt of the backtrace:

[...]
#7  0xc0f9fee7 in calltrap () at /usr/src/sys/i386/i386/exception.s:173
#8  0xd00f5759 in ext2_i2ei (ip=0xcab8f100, ei=0xe17e0f80)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_inode_cnv.c:152
#9  0xd00f4a56 in ext2_update (vp=0xce0f38e0, waitfor=1)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_inode.c:91
#10 0xd00fad12 in ext2_makeinode (mode=8, dvp=0xcc69f11c, vpp=0xeffeab88, 
    cnp=0xeffeab9c)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_vnops.c:1586
#11 0xc0fdd612 in VOP_CREATE_APV (vop=0xd00fe3a0, a=0xeffeaae8)
    at vnode_if.c:260
#12 0xc0b9d989 in vn_open_cred (ndp=0xeffeab5c, flagp=0xeffeac24, 
    cmode=<value optimized out>, vn_open_flags=0, cred=0xc9ee7100, 
    fp=0xcafea508) at vnode_if.h:109
#13 0xc0b9de6b in vn_open (ndp=0xeffeab5c, flagp=0xeffeac24, cmode=493, 
    fp=0xcafea508) at /usr/src/sys/kern/vfs_vnops.c:113
#14 0xc0b99460 in kern_openat (td=0xc8420900, fd=-100, 
    path=0x284a61a0 <Address 0x284a61a0 out of bounds>, 
    pathseg=UIO_USERSPACE, flags=2562, mode=493)
    at /usr/src/sys/kern/vfs_syscalls.c:1128
#15 0xc0b998b5 in kern_open (td=0xc8420900, 
    path=0x284a61a0 <Address 0x284a61a0 out of bounds>, 
    pathseg=UIO_USERSPACE, flags=2561, mode=493)
    at /usr/src/sys/kern/vfs_syscalls.c:1079
#16 0xc0b998f0 in sys_open (td=0xc8420900, uap=0xeffeaccc)
    at /usr/src/sys/kern/vfs_syscalls.c:1055
#17 0xc0fb6869 in syscall (frame=0xeffead08) at subr_syscall.c:142
#18 0xc0f9ff8c in Xint0x80_syscall ()
    at /usr/src/sys/i386/i386/exception.s:279

When kgdb'ing into frame 8, the pointer to ei seems not to be valid:

(kgdb) frame 8
#8  0xd00f5759 in ext2_i2ei (ip=0xcab8f100, ei=0xe17e0f80)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_inode_cnv.c:152
152             ei->e2di_ctime_extra = NSEC_TO_XTIME(ip->i_ctimensec);
(kgdb) print *ip
$1 = {i_vnode = 0xce0f38e0, i_ump = 0xccadc240, i_flag = 0, i_number = 122888, 
  i_e2fs = 0xc7798c00, i_modrev = 62488400780442, i_count = 0, i_endoff = 0, 
  i_diroff = 0, i_offset = 0, i_block_group = 60, i_next_alloc_block = 0, 
  i_next_alloc_goal = 0, i_mode = 33261, i_nlink = 1, i_uid = 0, i_gid = 0, 
  i_size = 0, i_blocks = 0, i_atime = 1454332232, i_mtime = 1454332232, 
  i_ctime = 1454332232, i_birthtime = 1454332232, i_mtimensec = 700120000, 
  i_atimensec = 700120000, i_ctimensec = 700120000, i_birthnsec = 700118000, 
  i_gen = 1784569991, i_flags = 0, i_db = {0 <repeats 12 times>}, i_ib = {0, 
    0, 0}, i_ext_cache = {ec_start = 0, ec_blk = 0, ec_len = 0, ec_type = 0}}
(kgdb) print *ei
Cannot access memory at address 0xe17e0f80

Some information from the previous frame:

(kgdb) frame 9
#9  0xd00f4a56 in ext2_update (vp=0xce0f38e0, waitfor=1)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_inode.c:91
91              ext2_i2ei(ip, (struct ext2fs_dinode *)((char *)bp->b_data +
(kgdb) print bp
$2 = (struct buf *) 0xe112a8a8
(kgdb) print *bp                                                                
$3 = {b_bufobj = 0xcbe062e4, b_bcount = 1024, b_caller1 = 0x0, 
  b_data = 0xe17e0c00 "íA", b_error = 0, b_iocmd = 2 '\002', 
  b_ioflags = 2 '\002', b_iooffset = 503319552, b_resid = 0, b_iodone = 0, 
  b_blkno = 983046, b_offset = 503319552, b_bobufs = {tqe_next = 0x0, 
    tqe_prev = 0xe1231828}, b_left = 0xe12317f0, b_right = 0x0, b_vflags = 0, 
  b_freelist = {tqe_next = 0x0, tqe_prev = 0xe123183c}, b_qindex = 2, 
  b_flags = 2684354720, b_xflags = 1 '\001', b_lock = {lock_object = {
      lo_name = 0xc10fe54f "bufwait", lo_flags = 108199936, lo_data = 0, 
      lo_witness = 0x0}, lk_lock = 3359770880, lk_exslpfail = 0, lk_timo = 0, 
    lk_pri = 96}, b_bufsize = 1024, b_runningbufspace = 0, 
  b_kvabase = 0xe17e0000 "#", b_kvaalloc = 0x0, b_kvasize = 16384, 
  b_lblkno = 983046, b_vp = 0xcbe06238, b_dirtyoff = 0, b_dirtyend = 0, 
  b_rcred = 0x0, b_wcred = 0x0, b_saveaddr = 0xe17e0000, b_pager = {
    pg_reqpage = 0}, b_cluster = {cluster_head = {tqh_first = 0x0, 
      tqh_last = 0xe11ad6f0}, cluster_entry = {tqe_next = 0x0, 
      tqe_prev = 0xe11ad6f0}}, b_pages = {0xc51334b0, 0x0 <repeats 31 times>}, 
  b_npages = 1, b_dep = {lh_first = 0x0}, b_fsprivate1 = 0x0, 
  b_fsprivate2 = 0x0, b_fsprivate3 = 0x0, b_pin_count = 0}

Please tell me what information I can provide, to help tracking this problem down.
Comment 1 Arrigo Marchiori 2016-02-01 14:31:23 UTC
Created attachment 166396 [details]
/var/crash/core.txt from the first panic
Comment 2 Arrigo Marchiori 2016-02-01 14:32:15 UTC
Created attachment 166397 [details]
/var/crash/core.txt from the second panic
Comment 3 Arrigo Marchiori 2016-02-01 15:10:14 UTC
The panic is also reproducible when writing to a md(4) instead of a USB drive.
The stack trace is analogous.

(kgdb) bt
#0  doadump (textdump=1) at pcpu.h:250
#1  0xc0aed3ae in kern_reboot (howto=260)
    at /usr/src/sys/kern/kern_shutdown.c:454
#2  0xc0aed6a5 in panic (fmt=<value optimized out>)
    at /usr/src/sys/kern/kern_shutdown.c:642
#3  0xc0d70ede in vm_fault_hold (map=0xc1b8d000, vaddr=3799322624, 
    fault_type=2 '\002', fault_flags=0, m_hold=0x0)
    at /usr/src/sys/vm/vm_fault.c:289
#4  0xc0d7355b in vm_fault (map=0xc1b8d000, vaddr=3799322624, 
    fault_type=<value optimized out>, fault_flags=0)
    at /usr/src/sys/vm/vm_fault.c:229
#5  0xc0fb619f in trap_pfault (frame=0xf0a8c964, usermode=0, eva=3799322628)
    at /usr/src/sys/i386/i386/trap.c:932
#6  0xc0fb744b in trap (frame=0xf0a8c964) at /usr/src/sys/i386/i386/trap.c:553
#7  0xc0f9fee7 in calltrap () at /usr/src/sys/i386/i386/exception.s:173
#8  0xcc966759 in ext2_i2ei (ip=0xc7ba8300, ei=0xe2750f80)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_inode_cnv.c:152
#9  0xcc965a56 in ext2_update (vp=0xc99c5470, waitfor=1)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_inode.c:91
#10 0xcc96bd12 in ext2_makeinode (mode=8, dvp=0xc99c46a8, vpp=0xf0a8cb88, 
    cnp=0xf0a8cb9c)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_vnops.c:1586
#11 0xc0fdd612 in VOP_CREATE_APV (vop=0xcc96f3a0, a=0xf0a8cae8)
    at vnode_if.c:260
#12 0xc0b9d989 in vn_open_cred (ndp=0xf0a8cb5c, flagp=0xf0a8cc24, 
    cmode=<value optimized out>, vn_open_flags=0, cred=0xc8bcf600, 
    fp=0xc940bdc8) at vnode_if.h:109
#13 0xc0b9de6b in vn_open (ndp=0xf0a8cb5c, flagp=0xf0a8cc24, cmode=493, 
    fp=0xc940bdc8) at /usr/src/sys/kern/vfs_vnops.c:113
#14 0xc0b99460 in kern_openat (td=0xca383900, fd=-100, 
    path=0x284a61a0 <Address 0x284a61a0 out of bounds>, pathseg=UIO_USERSPACE, 
    flags=2562, mode=493) at /usr/src/sys/kern/vfs_syscalls.c:1128
#15 0xc0b998b5 in kern_open (td=0xca383900, 
    path=0x284a61a0 <Address 0x284a61a0 out of bounds>, pathseg=UIO_USERSPACE, 
    flags=2561, mode=493) at /usr/src/sys/kern/vfs_syscalls.c:1079
#16 0xc0b998f0 in sys_open (td=0xca383900, uap=0xf0a8cccc)
    at /usr/src/sys/kern/vfs_syscalls.c:1055
#17 0xc0fb6869 in syscall (frame=0xf0a8cd08) at subr_syscall.c:142
#18 0xc0f9ff8c in Xint0x80_syscall () at /usr/src/sys/i386/i386/exception.s:279

(kgdb) frame 8
#8  0xcc966759 in ext2_i2ei (ip=0xc7ba8300, ei=0xe2750f80)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_inode_cnv.c:152
152             ei->e2di_ctime_extra = NSEC_TO_XTIME(ip->i_ctimensec);
(kgdb) print *ip
$1 = {i_vnode = 0xc99c5470, i_ump = 0xc7b92380, i_flag = 0, i_number = 49160, 
  i_e2fs = 0xc7858c00, i_modrev = 18475684767084, i_count = 0, i_endoff = 0, 
  i_diroff = 0, i_offset = 0, i_block_group = 24, i_next_alloc_block = 0, 
  i_next_alloc_goal = 0, i_mode = 33261, i_nlink = 1, i_uid = 0, i_gid = 0, 
  i_size = 0, i_blocks = 0, i_atime = 1454338085, i_mtime = 1454338085, 
  i_ctime = 1454338085, i_birthtime = 1454338085, i_mtimensec = 522810000, 
  i_atimensec = 522810000, i_ctimensec = 522810000, i_birthnsec = 522809000, 
  i_gen = 679956546, i_flags = 0, i_db = {0 <repeats 12 times>}, i_ib = {0, 0, 
    0}, i_ext_cache = {ec_start = 0, ec_blk = 0, ec_len = 0, ec_type = 0}}
(kgdb) print *ei
Cannot access memory at address 0xe2750f80

(kgdb) frame 9
#9  0xcc965a56 in ext2_update (vp=0xc99c5470, waitfor=1)
    at /usr/src/sys/modules/ext2fs/../../fs/ext2fs/ext2_inode.c:91
91              ext2_i2ei(ip, (struct ext2fs_dinode *)((char *)bp->b_data +
(kgdb) print *vp
$2 = {v_type = VREG, v_tag = 0xcc96e830 "ext2fs", v_op = 0xcc96f3a0, 
  v_data = 0xc7ba8300, v_mount = 0xc7dc77ec, v_nmntvnodes = {tqe_next = 0x0, 
    tqe_prev = 0xc99c56bc}, v_un = {vu_mount = 0x0, vu_socket = 0x0, 
    vu_cdev = 0x0, vu_fifoinfo = 0x0}, v_hashlist = {le_next = 0x0, 
    le_prev = 0xc793f988}, v_hash = 49160, v_cache_src = {lh_first = 0x0}, 
  v_cache_dst = {tqh_first = 0x0, tqh_last = 0xc99c54a0}, v_cache_dd = 0x0, 
  v_cstart = 0, v_lasta = 0, v_lastw = 0, v_clen = 0, v_lock = {lock_object = {
      lo_name = 0xcc96e830 "ext2fs", lo_flags = 108199944, lo_data = 0, 
      lo_witness = 0x0}, lk_lock = 3392682240, lk_exslpfail = 0, lk_timo = 51, 
    lk_pri = 96}, v_interlock = {lock_object = {
      lo_name = 0xc11003e9 "vnode interlock", lo_flags = 16973824, 
      lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}, v_vnlock = 0xc99c54c8, 
  v_holdcnt = 1, v_usecount = 1, v_iflag = 512, v_vflag = 0, v_writecount = 0, 
  v_actfreelist = {tqe_next = 0xc99c56a8, tqe_prev = 0xc7dc782c}, v_bufobj = {
    bo_mtx = {lock_object = {lo_name = 0xc11003f9 "bufobj interlock", 
        lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}, 
    bo_clean = {bv_hd = {tqh_first = 0x0, tqh_last = 0xc99c5530}, 
      bv_root = 0x0, bv_cnt = 0}, bo_dirty = {bv_hd = {tqh_first = 0x0, 
        tqh_last = 0xc99c5540}, bv_root = 0x0, bv_cnt = 0}, bo_numoutput = 0, 
    bo_flag = 0, bo_ops = 0xc1371e80, bo_bsize = 1024, bo_object = 0x0, 
    bo_synclist = {le_next = 0x0, le_prev = 0x0}, bo_private = 0xc99c5470, 
    __bo_vnode = 0xc99c5470}, v_pollinfo = 0x0, v_label = 0x0, v_lockf = 0x0, 
  v_rl = {rl_waiters = {tqh_first = 0x0, tqh_last = 0xc99c5580}, 
    rl_currdep = 0x0}}
Comment 4 Arrigo Marchiori 2016-02-01 15:23:33 UTC
Running e2fsck on the md(4)-backed file, after reboot:

# e2fsck /dev/md0s1
e2fsck 1.42.13 (17-May-2015)
/dev/md0s1 was not cleanly unmounted, check forced.
Pass 1: Checking inodes, blocks, and sizes
Inode 30721, i_size is 24, should be 1024.  Fix<y>? yes
Inode 49154 is in use, but has dtime set.  Fix<y>? yes
Inode 110593, i_size is 24, should be 1024.  Fix<y>? yes
Inode 126977, i_size is 24, should be 1024.  Fix<y>? yes
Pass 2: Checking directory structure
Pass 3: Checking directory connectivity
Pass 4: Checking reference counts
Pass 5: Checking group summary information
Block bitmap differences:  +123139 +(196867--196880) +197137 +(197426--197445) +197702 +(197876--197888) +442627 +508163
Fix<y>? yes
Free blocks count wrong for group #15 (7934, counted=7933).
Fix<y>? yes
Free blocks count wrong for group #24 (7934, counted=7885).
Fix<y>? yes
Free blocks count wrong for group #54 (7934, counted=7933).
Fix<y>? yes
Free blocks count wrong for group #62 (7934, counted=7933).
Fix<y>? yes
Free blocks count wrong (497201, counted=497149).
Fix<y>? yes
Inode bitmap differences:  +30721 +(49153--49159) +110593 +126977
Fix<y>? yes
Free inodes count wrong for group #15 (2048, counted=2047).
Fix<y>? yes
Directories count wrong for group #15 (0, counted=1).
Fix<y>? yes
Free inodes count wrong for group #24 (2048, counted=2041).
Fix<y>? yes
Directories count wrong for group #24 (0, counted=1).
Fix<y>? yes
Free inodes count wrong for group #54 (2048, counted=2047).
Fix<y>? yes
Directories count wrong for group #54 (0, counted=1).
Fix<y>? yes
Free inodes count wrong for group #62 (2048, counted=2047).
Fix<y>? yes
Directories count wrong for group #62 (0, counted=1).
Fix<y>? yes
Free inodes count wrong (131061, counted=131051).
Fix<y>? yes

/dev/md0s1: ***** FILE SYSTEM WAS MODIFIED *****
/dev/md0s1: 21/131072 files (9.5% non-contiguous), 27135/524284 blocks
Comment 5 Arrigo Marchiori 2016-02-01 16:01:44 UTC
FWIW, the problem is _not_ reproducible on my 10-RELEASE x86-64 machine:

# uname -a
FreeBSD myhost 10.1-RELEASE-p26 FreeBSD 10.1-RELEASE-p26 #0: Wed Jan 13 20:59:29 UTC 2016     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64
Comment 6 Pedro F. Giffuni freebsd_committer 2016-02-03 04:57:59 UTC
Hello Arrigo;

Thank you so much for testing!

Please try this:

- On 9-stable revert r294971.
- Try to reproduce on 10-stable.

Both 9-stable and 10-stable have a chenge to use the extra timestamps. These are supposed to be unused in ext3.

Pedro.
Comment 7 Arrigo Marchiori 2016-02-03 08:33:11 UTC
(In reply to Pedro F. Giffuni from comment #6)

Hello Pedro,

thank you for taking care of this.

[...]
> Please try this:
> 
> - On 9-stable revert r294971.

9-STABLE r294970 does not show this problem.
That change may be the culprit?

> - Try to reproduce on 10-stable.

I don't have any 10-stable machines. I am sorry.
Comment 8 Pedro F. Giffuni freebsd_committer 2016-02-03 14:25:22 UTC
Hi again;

(In reply to Arrigo Marchiori from comment #7)

The change is pretty much the main suspect. It did pass some basic tests before being committed but there may be special cases.

I appreciate the report. One more question what is the inode size of the filesystem?
Comment 9 commit-hook freebsd_committer 2016-02-03 14:31:41 UTC
A commit references this bug:

Author: pfg
Date: Wed Feb  3 14:31:24 UTC 2016
New revision: 295209
URL: https://svnweb.freebsd.org/changeset/base/295209

Log:
  Revert r294695:
  ext2fs: passthrough any extra timestamps to the dinode struct.

  While it passed the classic testing, the change appears to have
  caused some regression and still requires some more precautions.

  PR:		206820
  MFC after:	3 days

Changes:
  head/sys/fs/ext2fs/ext2_inode_cnv.c
Comment 10 Arrigo Marchiori 2016-02-03 14:54:38 UTC
Created attachment 166499 [details]
Output of dumpe2fs on an ext2 filesystem correctly populated by stable r294970

This filesystem was created into a 512 megabyte md(4), with the mkfs.ext3 and tune2fs invocations from the bug decription.

Inode count: 131072
Block count: 524280
Block size: 1024
Fragment size: 1024
Inode size: 128
Comment 11 Pedro F. Giffuni freebsd_committer 2016-02-03 16:39:15 UTC
(In reply to Arrigo Marchiori from comment #10)
Thank you Arrigo!

That is the root cause: The inode is too small and our implementation is not being careful about the inode size. I didn't notice in my testing because I ran my tests in a USB mem with the default ext3 settings.

Reverting is a workaround ... for now.
Comment 12 commit-hook freebsd_committer 2016-02-06 16:59:49 UTC
A commit references this bug:

Author: pfg
Date: Sat Feb  6 16:58:56 UTC 2016
New revision: 295353
URL: https://svnweb.freebsd.org/changeset/base/295353

Log:
  MFC r295209;
  Revert r294695; passthrough any extra timestamps to the dinode struct.

  The original ext2fs change worked fine on disks formated with default
  values, but it was the cause of a regression when inodes are small.
  Revert it for now, while we figure out safer ways pass such values,

  PR:		206820
  Approved by:	re

Changes:
_U  stable/10/
  stable/10/sys/fs/ext2fs/ext2_inode_cnv.c
Comment 13 commit-hook freebsd_committer 2016-02-06 17:10:52 UTC
A commit references this bug:

Author: pfg
Date: Sat Feb  6 17:10:47 UTC 2016
New revision: 295354
URL: https://svnweb.freebsd.org/changeset/base/295354

Log:
  MFC r295209;
  Revert r294695; passthrough any extra timestamps to the dinode struct.

  The original ext2fs change worked fine on disks formated with default
  values, but it was the cause of a regression when inodes are small.
  Revert it for now, while we figure out safer ways pass such values,

  PR:		206820

Changes:
_U  stable/9/sys/
_U  stable/9/sys/fs/
  stable/9/sys/fs/ext2fs/ext2_inode_cnv.c
Comment 14 Pedro F. Giffuni freebsd_committer 2016-02-06 18:02:33 UTC
Fixed on all supported versions.
After 10.3 Release I will be considering a better enhancement.

Huge thanks for all the testing!!
Comment 15 Arrigo Marchiori 2016-02-08 11:48:27 UTC
(In reply to Pedro F. Giffuni from comment #14)
> Fixed on all supported versions.
> After 10.3 Release I will be considering a better enhancement.
> 
> Huge thanks for all the testing!!

Thank you for the quick fix!