mtdchar kernel oops

mtdchar kernel oops

[Joel Reardon]

I think that this patch:
"mtdchar: kill persistently held vfsmount"
http://permalink.gmane.org/gmane.linux.kernel.commits.head/314175

has started causing kernel oops's when running ubiformat. The oops is
occuring in fs/namespace.c's mnt_add_count() line:
        this_cpu_add(mnt->mnt_pcp->mnt_count, n);

with the stack trace:
mntget()
simple_pin_fs()
mtdchar_open()

Cheers,
Joel

Re: mtdchar kernel oops

[Fabio Estevam]

On Sun, Apr 15, 2012 at 8:58 AM, Joel Reardon <joel@clambassador.com> wrote:
> I think that this patch:
> "mtdchar: kill persistently held vfsmount"
> http://permalink.gmane.org/gmane.linux.kernel.commits.head/314175
>
> has started causing kernel oops's when running ubiformat. The oops is
> occuring in fs/namespace.c's mnt_add_count() line:
>        this_cpu_add(mnt->mnt_pcp->mnt_count, n);

I also see kernel oops when running flash_eraseall on a SPI NOR flash.

If this patch is reverted the flash_eraseall operation is successful.

Re: mtdchar kernel oops

[Fabio Estevam]

On Sun, Apr 15, 2012 at 11:19 AM, Fabio Estevam <festevam@gmail.com> wrote:
> On Sun, Apr 15, 2012 at 8:58 AM, Joel Reardon <joel@clambassador.com> wrote:
>> I think that this patch:
>> "mtdchar: kill persistently held vfsmount"
>> http://permalink.gmane.org/gmane.linux.kernel.commits.head/314175
>>
>> has started causing kernel oops's when running ubiformat. The oops is
>> occuring in fs/namespace.c's mnt_add_count() line:
>>        this_cpu_add(mnt->mnt_pcp->mnt_count, n);
>
> I also see kernel oops when running flash_eraseall on a SPI NOR flash.
>
> If this patch is reverted the flash_eraseall operation is successful.

I am no longer getting kernel oops on 3.4.0-rc3-next-20120418.

Re: mtdchar kernel oops

[Al Viro]

On Sun, Apr 15, 2012 at 01:58:39PM +0200, Joel Reardon wrote:
> I think that this patch:
> "mtdchar: kill persistently held vfsmount"
> http://permalink.gmane.org/gmane.linux.kernel.commits.head/314175
> 
> has started causing kernel oops's when running ubiformat. The oops is
> occuring in fs/namespace.c's mnt_add_count() line:
>         this_cpu_add(mnt->mnt_pcp->mnt_count, n);
> 
> with the stack trace:
> mntget()
> simple_pin_fs()
> mtdchar_open()

Check if commit c65390f4dd49755863f6d772ec538ee4757c08d7
Author: Al Viro <viro@zeniv.linux.org.uk>
Date:   Mon Apr 9 01:36:28 2012 -0400

    fix breakage in mtdchar_open(), sanitize failure exits

has fixed that.

Re: mtdchar kernel oops

[Joel Reardon]

Nope, still there.

As example trace:

[  162.141319] BUG: unable to handle kernel paging request at 367fb000
[  162.141405] IP: [<c023614f>] mntget+0xf/0x20
[  162.141463] *pde = 00000000
[  162.141499] Oops: 0002 [#1] SMP
[  162.141542] Modules linked in: mtdchar nandsim nand nand_ids mtd
nand_ecc aes_i586 aes_generic parport_pc ppdev dm_crypt snd_hda_codec_hdmi
snd_hda_codec_conexant snd_hda_intel snd_hda_codec btusb bluetooth
snd_hwdep snd_pcm_oss snd_mixer_oss snd_pcm thinkpad_acpi binfmt_misc
snd_seq_dummy snd_seq_oss snd_seq_midi arc4 snd_rawmidi snd_seq_midi_event
snd_seq iwlwifi mac80211 snd_timer snd_seq_device snd coretemp tpm_tis
cfg80211 psmouse serio_raw joydev soundcore snd_page_alloc tpm microcode
tpm_bios nvram lp parport fbcon i915 tileblit font bitblit softcursor
drm_kms_helper usbhid hid mmc_block drm mxm_wmi crc32c_intel firewire_ohci
sdhci_pci sdhci ahci libahci firewire_core crc_itu_t i2c_algo_bit video
intel_agp intel_gtt agpgart e1000e [last unloaded: kvm]
[  162.142435]
[  162.142456] Pid: 2260, comm: ubiformat Not tainted
[  162.142569] EIP: 0060:[<c023614f>] EFLAGS: 00010282 CPU: 1
[  162.142632] EIP is at mntget+0xf/0x20
[  162.142674] EAX: f6804c10 EBX: f917ff38 ECX: 00000073 EDX: 00000000
[  162.142744] ESI: f917ff34 EDI: 00000000 EBP: f0847db8 ESP: f0847db8
[  162.142815]  DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[  162.142875] CR0: 80050033 CR2: 367fb000 CR3: 36b56000 CR4: 000007d0
[  162.142946] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[  162.143016] DR6: ffff0ff0 DR7: 00000400
[  162.143060] Process ubiformat (pid: 2260, ti=f0846000 task=f43fa5e0
task.ti=f0846000)
[  162.143146] Stack:
[  162.143170]  f0847dd8 c023b888 f4834c00 f0847df0 c0a7088c fffffff3
f3df00c0 00000000
[  162.143271]  f0847df0 f917fa34 c0220231 00000000 f6f11440 00000000
f0847e14 c0220252
[  162.143372]  f3df00c0 f2795b70 c0a706bc 00000000 f3df00c0 f2795b70
f11ff500 f0847e3c
[  162.143474] Call Trace:
[  162.143507]  [<c023b888>] simple_pin_fs+0x38/0xb0
[  162.143570]  [<f917fa34>] mtdchar_open+0x44/0x1a8 [mtdchar]
[  162.143636]  [<c0220231>] ? chrdev_open+0x71/0x180
[  162.143692]  [<c0220252>] chrdev_open+0x92/0x180
[  162.143749]  [<c021a2ee>] __dentry_open+0x1ee/0x2a0
[  162.147258]  [<c021b72e>] nameidata_to_filp+0x6e/0x80
[  162.150750]  [<c02201c0>] ? cdev_put+0x20/0x20
[  162.154212]  [<c02286a7>] do_last+0x287/0x800
[  162.157582]  [<c0229c45>] path_openat+0xa5/0x350
[  162.160949]  [<c022a001>] do_filp_open+0x31/0x80
[  162.164289]  [<c0234e93>] ? alloc_fd+0xa3/0xe0
[  162.167577]  [<c0225cf5>] ? getname_flags+0xe5/0x160
[  162.170862]  [<c021b81a>] do_sys_open+0xda/0x1a0
[  162.174118]  [<c021b912>] sys_open+0x32/0x40
[  162.177363]  [<c0615c63>] sysenter_do_call+0x12/0x28
[  162.180564] Code: fe ff ff 89 d8 31 db e8 40 fa ff ff e9 6c ff ff ff 8d
74 26 00 8d bc 27 00 00 00 00 55 89 e5 3e 8d 74 26 00 85 c0 74 06 8b 50 0c
<64> ff 02 5d c3 8d b6 00 00 00 00 8d bf 00 00 00 00 55 89 e5 53
[  162.187488] EIP: [<c023614f>] mntget+0xf/0x20 SS:ESP 0068:f0847db8
[  162.190993] CR2: 00000000367fb000
[  162.261991] ---[ end trace 1e4490d14c39e9e1 ]---


It also occasionally does it while modprobing nandsim and claims
"mtd_probe" as the process.

Cheers,
Joel

On Sun, 15 Apr 2012, Al Viro wrote:

> On Sun, Apr 15, 2012 at 01:58:39PM +0200, Joel Reardon wrote:
> > I think that this patch:
> > "mtdchar: kill persistently held vfsmount"
> > http://permalink.gmane.org/gmane.linux.kernel.commits.head/314175
> >
> > has started causing kernel oops's when running ubiformat. The oops is
> > occuring in fs/namespace.c's mnt_add_count() line:
> >         this_cpu_add(mnt->mnt_pcp->mnt_count, n);
> >
> > with the stack trace:
> > mntget()
> > simple_pin_fs()
> > mtdchar_open()
>
> Check if commit c65390f4dd49755863f6d772ec538ee4757c08d7
> Author: Al Viro <viro@zeniv.linux.org.uk>
> Date:   Mon Apr 9 01:36:28 2012 -0400
>
>     fix breakage in mtdchar_open(), sanitize failure exits
>
> has fixed that.
>

Re: mtdchar kernel oops

[Al Viro]

On Sun, Apr 15, 2012 at 07:57:51PM +0200, Joel Reardon wrote:
> Nope, still there.
> 
> As example trace:
> 
> [  162.141319] BUG: unable to handle kernel paging request at 367fb000
> [  162.141405] IP: [<c023614f>] mntget+0xf/0x20
> [  162.141463] *pde = 00000000
> [  162.141499] Oops: 0002 [#1] SMP
> [  162.141542] Modules linked in: mtdchar nandsim nand nand_ids mtd
> nand_ecc aes_i586 aes_generic parport_pc ppdev dm_crypt snd_hda_codec_hdmi
> snd_hda_codec_conexant snd_hda_intel snd_hda_codec btusb bluetooth
> snd_hwdep snd_pcm_oss snd_mixer_oss snd_pcm thinkpad_acpi binfmt_misc
> snd_seq_dummy snd_seq_oss snd_seq_midi arc4 snd_rawmidi snd_seq_midi_event
> snd_seq iwlwifi mac80211 snd_timer snd_seq_device snd coretemp tpm_tis
> cfg80211 psmouse serio_raw joydev soundcore snd_page_alloc tpm microcode
> tpm_bios nvram lp parport fbcon i915 tileblit font bitblit softcursor
> drm_kms_helper usbhid hid mmc_block drm mxm_wmi crc32c_intel firewire_ohci
> sdhci_pci sdhci ahci libahci firewire_core crc_itu_t i2c_algo_bit video
> intel_agp intel_gtt agpgart e1000e [last unloaded: kvm]
> [  162.142435]
> [  162.142456] Pid: 2260, comm: ubiformat Not tainted
> [  162.142569] EIP: 0060:[<c023614f>] EFLAGS: 00010282 CPU: 1
> [  162.142632] EIP is at mntget+0xf/0x20
> [  162.142674] EAX: f6804c10 EBX: f917ff38 ECX: 00000073 EDX: 00000000
> [  162.142744] ESI: f917ff34 EDI: 00000000 EBP: f0847db8 ESP: f0847db8
> [  162.142815]  DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
> [  162.142875] CR0: 80050033 CR2: 367fb000 CR3: 36b56000 CR4: 000007d0
> [  162.142946] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [  162.143016] DR6: ffff0ff0 DR7: 00000400
> [  162.143060] Process ubiformat (pid: 2260, ti=f0846000 task=f43fa5e0
> task.ti=f0846000)
> [  162.143146] Stack:
> [  162.143170]  f0847dd8 c023b888 f4834c00 f0847df0 c0a7088c fffffff3
> f3df00c0 00000000
> [  162.143271]  f0847df0 f917fa34 c0220231 00000000 f6f11440 00000000
> f0847e14 c0220252
> [  162.143372]  f3df00c0 f2795b70 c0a706bc 00000000 f3df00c0 f2795b70
> f11ff500 f0847e3c
> [  162.143474] Call Trace:
> [  162.143507]  [<c023b888>] simple_pin_fs+0x38/0xb0
> [  162.143570]  [<f917fa34>] mtdchar_open+0x44/0x1a8 [mtdchar]
> [  162.143636]  [<c0220231>] ? chrdev_open+0x71/0x180
> [  162.143692]  [<c0220252>] chrdev_open+0x92/0x180
> [  162.143749]  [<c021a2ee>] __dentry_open+0x1ee/0x2a0
> [  162.147258]  [<c021b72e>] nameidata_to_filp+0x6e/0x80
> [  162.150750]  [<c02201c0>] ? cdev_put+0x20/0x20
> [  162.154212]  [<c02286a7>] do_last+0x287/0x800
> [  162.157582]  [<c0229c45>] path_openat+0xa5/0x350
> [  162.160949]  [<c022a001>] do_filp_open+0x31/0x80
> [  162.164289]  [<c0234e93>] ? alloc_fd+0xa3/0xe0
> [  162.167577]  [<c0225cf5>] ? getname_flags+0xe5/0x160
> [  162.170862]  [<c021b81a>] do_sys_open+0xda/0x1a0
> [  162.174118]  [<c021b912>] sys_open+0x32/0x40
> [  162.177363]  [<c0615c63>] sysenter_do_call+0x12/0x28
> [  162.180564] Code: fe ff ff 89 d8 31 db e8 40 fa ff ff e9 6c ff ff ff 8d
> 74 26 00 8d bc 27 00 00 00 00 55 89 e5 3e 8d 74 26 00 85 c0 74 06 8b 50 0c
> <64> ff 02 5d c3 8d b6 00 00 00 00 8d bf 00 00 00 00 55 89 e5 53
> [  162.187488] EIP: [<c023614f>] mntget+0xf/0x20 SS:ESP 0068:f0847db8
> [  162.190993] CR2: 00000000367fb000
> [  162.261991] ---[ end trace 1e4490d14c39e9e1 ]---
> 
> 
> It also occasionally does it while modprobing nandsim and claims
> "mtd_probe" as the process.

Interesting...  Can't reproduce here and trace makes very little sense -
instructions around that point are
	8b 50 0c                mov    0xc(%eax),%edx
	64 ff 02                incl   %fs:(%edx)
and values in registers do not match the GFP address at all (well, %cr2
does, of course, but that's it).  How do you reproduce that sucker?
I don't have hardware mtd devices, so I tried to use block2mtd and ran
ubiformat on resulting /dev/mtd0.  Worked fine and it definitely had
done mtdchar_open()...

Could you add printk into mtdchar_open(), dumping mnt and count values
right after simple_pin_fs() call?

Re: mtdchar kernel oops

[Joel Reardon]

The troubled asm pair corresponds to this line:
this_cpu_add(mnt->mnt_pcp->mnt_count, n) in  the inline mnt_add_count().
So I suppose that perhaps either mnt is bad, or mnt_pcp is bad.

I'm using nandsim to simulate the mtd device. Steps are simple, load the
modules:
nand_ecc nand nand_ids mtd  mtd_blkdevs mtdblock mtdchar
nandsim first_id_byte=0x20 second_id_byte=0xa5 third_id_byte=0x00 fourth_id_byte=0x15 parts=0xa40 rptwear=1000

then `ubiformat /dev/mtd0` does the oops.

>
> Could you add printk into mtdchar_open(), dumping mnt and count values
> right after simple_pin_fs() call?
>

It oopses before it returns from the simple_pin_fs call, so that won't be
possible...

Cheers,
Joel

Re: mtdchar kernel oops

[Al Viro]

On Mon, Apr 16, 2012 at 02:37:06PM +0200, Joel Reardon wrote:
> The troubled asm pair corresponds to this line:
> this_cpu_add(mnt->mnt_pcp->mnt_count, n) in  the inline mnt_add_count().
> So I suppose that perhaps either mnt is bad, or mnt_pcp is bad.
> 
> I'm using nandsim to simulate the mtd device. Steps are simple, load the
> modules:
> nand_ecc nand nand_ids mtd  mtd_blkdevs mtdblock mtdchar
> nandsim first_id_byte=0x20 second_id_byte=0xa5 third_id_byte=0x00 fourth_id_byte=0x15 parts=0xa40 rptwear=1000
> 
> then `ubiformat /dev/mtd0` does the oops.

Not here:

root@dizzy:~# modprobe nandsim first_id_byte=0x20 second_id_byte=0xa5 third_id_byte=0x00 fourth_id_byte=0x15 parts=0xa40 rptwear=1000
ubiformat: mtd0 (nand), size 343932928 bytes (328.0 MiB), 2624 eraseblocks of 131072 bytes (128.0 KiB), min. I/O size 2048 bytes
libscan: scanning eraseblock 2623 -- 100 % complete  
ubiformat: 2624 eraseblocks are supposedly empty
ubiformat: formatting eraseblock 2623 -- 100 % complete  
root@dizzy:~# uname -a
Linux dizzy 3.4.0-rc2+ #4 SMP Mon Apr 16 15:04:25 EDT 2012 x86_64 GNU/Linux

and no oopsen in sight...


> > Could you add printk into mtdchar_open(), dumping mnt and count values
> > right after simple_pin_fs() call?
> >
> 
> It oopses before it returns from the simple_pin_fs call, so that won't be
> possible...

Wha...?  You mean, that happens on the _first_ simple_pin_fs() call?
But that makes no damn sense whatsoever - we just do vfs_kern_mount(),
get a vfsmount from it (and not an ERR_PTR(), at that), then store
it into mnt and do mntget(mnt) followed by mntput(mnt).  If that really
happens when simple_pin_fs() gets called with mnt == NULL and count == 0,
we have much bigger problem on hands...

Please, slap such printks before and after simple_pin_fs() in mtdchar_open()
and before and after simple_release_fs() in mtdchar_close().  And verify that
you have commit c65390f4dd49755863f6d772ec538ee4757c08d7 in your tree.

Re: mtdchar kernel oops

[Joel Reardon]

Perhaps Artem can shed some light on this, I'm working on a branch he's
prepared. But if its not happening at your end then perhaps something's up
on mine; the oops log is rather bizzare. I'll remake it from scratch and
see what happens.

Cheers,
Joel

On Mon, 16 Apr 2012, Al Viro wrote:

> On Mon, Apr 16, 2012 at 02:37:06PM +0200, Joel Reardon wrote:
> > The troubled asm pair corresponds to this line:
> > this_cpu_add(mnt->mnt_pcp->mnt_count, n) in  the inline mnt_add_count().
> > So I suppose that perhaps either mnt is bad, or mnt_pcp is bad.
> >
> > I'm using nandsim to simulate the mtd device. Steps are simple, load the
> > modules:
> > nand_ecc nand nand_ids mtd  mtd_blkdevs mtdblock mtdchar
> > nandsim first_id_byte=0x20 second_id_byte=0xa5 third_id_byte=0x00 fourth_id_byte=0x15 parts=0xa40 rptwear=1000
> >
> > then `ubiformat /dev/mtd0` does the oops.
>
> Not here:
>
> root@dizzy:~# modprobe nandsim first_id_byte=0x20 second_id_byte=0xa5 third_id_byte=0x00 fourth_id_byte=0x15 parts=0xa40 rptwear=1000
> ubiformat: mtd0 (nand), size 343932928 bytes (328.0 MiB), 2624 eraseblocks of 131072 bytes (128.0 KiB), min. I/O size 2048 bytes
> libscan: scanning eraseblock 2623 -- 100 % complete
> ubiformat: 2624 eraseblocks are supposedly empty
> ubiformat: formatting eraseblock 2623 -- 100 % complete
> root@dizzy:~# uname -a
> Linux dizzy 3.4.0-rc2+ #4 SMP Mon Apr 16 15:04:25 EDT 2012 x86_64 GNU/Linux
>
> and no oopsen in sight...
>
>
> > > Could you add printk into mtdchar_open(), dumping mnt and count values
> > > right after simple_pin_fs() call?
> > >
> >
> > It oopses before it returns from the simple_pin_fs call, so that won't be
> > possible...
>
> Wha...?  You mean, that happens on the _first_ simple_pin_fs() call?
> But that makes no damn sense whatsoever - we just do vfs_kern_mount(),
> get a vfsmount from it (and not an ERR_PTR(), at that), then store
> it into mnt and do mntget(mnt) followed by mntput(mnt).  If that really
> happens when simple_pin_fs() gets called with mnt == NULL and count == 0,
> we have much bigger problem on hands...
>
> Please, slap such printks before and after simple_pin_fs() in mtdchar_open()
> and before and after simple_release_fs() in mtdchar_close().  And verify that
> you have commit c65390f4dd49755863f6d772ec538ee4757c08d7 in your tree.
>

Re: mtdchar kernel oops

[Artem Bityutskiy]

[-- Attachment #1: Type: text/plain, Size: 513 bytes --]

On Wed, 2012-04-18 at 14:55 +0200, Joel Reardon wrote:
> Perhaps Artem can shed some light on this, I'm working on a branch he's
> prepared. But if its not happening at your end then perhaps something's up
> on mine; the oops log is rather bizzare. I'll remake it from scratch and
> see what happens.

I am having paternity leave and will not be very responsive for few
weeks from now, sorry. Try to play with rebasing/clean
compilation/changing the compiler etc.

-- 
Best Regards,
Artem Bityutskiy

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 490 bytes --]