Message-ID: <1329428930.6062.4.camel@firefly>
Date:	Thu, 16 Feb 2012 16:48:50 -0500
From:	"Nathan A. Mourey II" <nmoureyii@...rr.com>
To:	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>
Cc:	"Srivatsa S. Bhat" <srivatsa.bhat@...ux.vnet.ibm.com>,
	Linux PM mailing list <linux-pm@...r.kernel.org>,
	"Rafael J. Wysocki" <rjw@...k.pl>, linux-fsdevel@...r.kernel.org
Subject: Re: Kernel bug with btrfs on laptop with external hd and suspend
 and resume.

I booted up my laptop with my eSATA drives attached and mounted.  I then
closed the lid without logging in.  It then when to sleep mode.  I was
wrong in my first post about the computer suspending.  It didn't suspend
to disk, as I would have noticed the hd light.  The drives where not
unplugged at any time.  It looks like the problem occurred when trying
to stop the disks.  I was able to do a hard reboot and the disk came up
fine.  Once again I hope that this helps.


Feb 14 14:46:39 firefly kernel: [   96.374559] Restarting tasks ...
Feb 14 14:46:39 firefly kernel: [   96.375986] XFS (sdb1): xfs_do_force_shutdown(0x1) called from line 1033 of file fs/xfs/xfs_buf.c.  Return address = 0xffffffffa05f18ba
Feb 14 14:46:39 firefly kernel: [   96.375993] XFS (sdb1): I/O Error Detected. Shutting down filesystem
Feb 14 14:46:39 firefly kernel: [   96.376017] XFS (sdb1): Please umount the filesystem and rectify the problem(s)
Feb 14 14:46:39 firefly kernel: [   96.384244] sd 4:0:0:0: [sdb] Synchronizing SCSI cache
Feb 14 14:46:39 firefly kernel: [   96.384280] sd 4:0:0:0: [sdb]  Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
Feb 14 14:46:39 firefly kernel: [   96.384284] sd 4:0:0:0: [sdb] Stopping disk
Feb 14 14:46:39 firefly kernel: [   96.384291] sd 4:0:0:0: [sdb] START_STOP FAILED
Feb 14 14:46:39 firefly kernel: [   96.384293] sd 4:0:0:0: [sdb]  Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
Feb 14 14:46:39 firefly kernel: [   96.384318] ata5.01: detaching (SCSI 4:1:0:0)
Feb 14 14:46:39 firefly kernel: [   96.385322] sd 4:1:0:0: [sdc] Synchronizing SCSI cache
Feb 14 14:46:39 firefly kernel: [   96.385349] sd 4:1:0:0: [sdc]  Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
Feb 14 14:46:39 firefly kernel: [   96.385352] sd 4:1:0:0: [sdc] Stopping disk
Feb 14 14:46:39 firefly kernel: [   96.385359] sd 4:1:0:0: [sdc] START_STOP FAILED
Feb 14 14:46:39 firefly kernel: [   96.385361] sd 4:1:0:0: [sdc]  Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
Feb 14 14:46:39 firefly dbus-daemon[1287]: ** Message: No devices in use, exit
Feb 14 14:46:39 firefly kernel: [   96.385496] done.
Feb 14 14:46:39 firefly kernel: [   96.508182] video LNXVIDEO:00: Restoring backlight state
Feb 14 14:46:39 firefly dbus-daemon[1287]: dbus[1287]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Feb 14 14:46:39 firefly dbus[1287]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Feb 14 14:46:39 firefly kernel: [   96.637185] XFS (sdb1): xfs_log_force: error 5 returned.
Feb 14 14:46:39 firefly kernel: [   96.637191] XFS (sdb1): xfs_do_force_shutdown(0x1) called from line 1033 of file fs/xfs/xfs_buf.c.  Return address = 0xffffffffa05f18ba
Feb 14 14:46:39 firefly kernel: [   96.637205] XFS (sdb1): xfs_log_force: error 5 returned.
Feb 14 14:46:39 firefly kernel: [   96.637212] XFS (sdb1): xfs_log_force: error 5 returned.
Feb 14 14:46:39 firefly kernel: [   96.638544] ------------[ cut here ]------------
Feb 14 14:46:39 firefly kernel: [   96.638796] kernel BUG at fs/btrfs/transaction.c:1337!
Feb 14 14:46:39 firefly kernel: [   96.639014] invalid opcode: 0000 [#1] SMP
Feb 14 14:46:39 firefly kernel: [   96.639014] CPU 1
Feb 14 14:46:39 firefly kernel: [   96.639014] Modules linked in: ppdev parport_pc lp parport ebtable_nat ebtables ipt_MASQUERADE iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge stp llc be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i cxgb4 cxgb3i libcxgbi cxgb3 mdio ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables nf_conntrack_netbios_ns nf_conntrack_broadcast nf_conntrack_ftp nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack binfmt_misc xfs arc4 snd_hda_codec_si3054 uvcvideo snd_hda_codec_realtek videodev snd_hda_intel snd_hda_codec microcode media v4l2_compat_ioctl32 usblp snd_hwdep snd_seq snd_seq_device snd_pcm snd_timer snd soundcore joydev iwlwifi mac80211 cfg80211 rfkill jmb38x_ms iTCO_wdt iTCO_vendor_support snd_page_alloc i2c_i801 serio_raw r8169 mii memstick vhost_net macvtap macvlan tun virtio_net kvm_intel kvm uinput nfsd lockd nfs_acl auth_rpcgss sunrpc btrfs
Feb 14 14:46:39 firefly kernel: zlib_deflate libcrc32c firewire_ohci sdhci_pci sdhci firewire_core crc_itu_t mmc_core nouveau ttm drm_kms_helper drm i2c_algo_bit i2c_core mxm_wmi wmi video [last unloaded: scsi_wait_scan]
Feb 14 14:46:39 firefly kernel: [   96.639014]
Feb 14 14:46:39 firefly kernel: [   96.639014] Pid: 2360, comm: umount Not tainted 3.2.5-3.fc16.x86_64 #1 System76, Inc. Serval Professional/Serval Professional
Feb 14 14:46:39 firefly kernel: [   96.639014] RIP: 0010:[<ffffffffa01c6f3c>]  [<ffffffffa01c6f3c>] btrfs_commit_transaction+0x81c/0x820 [btrfs]
Feb 14 14:46:39 firefly kernel: [   96.639014] RSP: 0018:ffff88011bd45d28  EFLAGS: 00010282
Feb 14 14:46:39 firefly kernel: [   96.648131] RAX: 00000000fffffffb RBX: ffff88011395ef00 RCX: 0000000000000000
Feb 14 14:46:39 firefly kernel: [   96.648131] RDX: 0000000000000000 RSI: 0000000001c67000 RDI: 0000000000000000
Feb 14 14:46:39 firefly kernel: [   96.648131] RBP: ffff88011bd45db8 R08: 0000000000002000 R09: 0000000000000010
Feb 14 14:46:39 firefly kernel: [   96.648131] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88012fd48800
Feb 14 14:46:39 firefly kernel: [   96.648131] R13: ffff88011395df78 R14: ffff88011395ef78 R15: 0000000000000000
Feb 14 14:46:39 firefly kernel: [   96.648131] FS:  00007ffcd6272800(0000) GS:ffff88013fd00000(0000) knlGS:0000000000000000
Feb 14 14:46:39 firefly kernel: [   96.648131] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Feb 14 14:46:39 firefly kernel: [   96.648131] CR2: 00007f1f50094a90 CR3: 000000011bc6a000 CR4: 00000000000406e0
Feb 14 14:46:39 firefly kernel: [   96.648131] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Feb 14 14:46:39 firefly kernel: [   96.648131] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Feb 14 14:46:39 firefly kernel: [   96.648131] Process umount (pid: 2360, threadinfo ffff88011bd44000, task ffff880109cb8000)
Feb 14 14:46:39 firefly kernel: [   96.648131] Stack:
Feb 14 14:46:39 firefly kernel: [   96.648131]  ffff88011bd45d58 0000000000000001 0000000000000000 ffff880109cb8000
Feb 14 14:46:39 firefly kernel: [   96.648131]  ffffffff81090440 ffff88011bd45d50 ffff88011bd45d50 ffffffffa01c7394
Feb 14 14:46:39 firefly kernel: [   96.648131]  7fffffffffffffff 0000000035684400 ffff88011bd45d78 ffff88012fd48800
Feb 14 14:46:39 firefly kernel: [   96.648131] Call Trace:
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff81090440>] ? remove_wait_queue+0x50/0x50
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffffa01c7394>] ? start_transaction+0x94/0x2a0 [btrfs]
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffffa01a221c>] btrfs_sync_fs+0x6c/0xf0 [btrfs]
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff811a56b3>] __sync_filesystem+0x63/0x90
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff811a575b>] sync_filesystem+0x4b/0x70
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff8117ae2b>] generic_shutdown_super+0x3b/0xd0
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff8117af56>] kill_anon_super+0x16/0x30
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff8117b30c>] deactivate_locked_super+0x3c/0xa0
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff8117bd7e>] deactivate_super+0x4e/0x70
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff811967d5>] mntput_no_expire+0xb5/0x100
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff8119755c>] sys_umount+0x6c/0x350
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff81183912>] ? path_put+0x22/0x30
Feb 14 14:46:39 firefly kernel: [   96.648131]  [<ffffffff815e9782>] system_call_fastpath+0x16/0x1b
Feb 14 14:46:39 firefly kernel: [   96.648131] Code: e9 9b f9 ff ff 0f 0b 0f 0b 0f 0b 0f 0b 0f 0b 0f 0b be fc 04 00 00 48 c7 c7 93 a0 21 a0 e8 5d 6e ea e0 e9 4d fb ff ff 0f 0b 0f 0b <0f> 0b 66 90 55 48 89 e5 53 48 83 ec 08 66 66 66 66 90 48 8b 77
Feb 14 14:46:39 firefly kernel: [   96.648131] RIP  [<ffffffffa01c6f3c>] btrfs_commit_transaction+0x81c/0x820 [btrfs]
Feb 14 14:46:39 firefly kernel: [   96.648131]  RSP <ffff88011bd45d28>
Feb 14 14:46:39 firefly systemd[1]: Unit build.mount entered failed state.
Feb 14 14:46:39 firefly dbus[1287]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Feb 14 14:46:39 firefly dbus-daemon[1287]: dbus[1287]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Feb 14 14:46:40 firefly kernel: [   97.346410] iwlwifi 0000:06:00.0: L1 Disabled; Enabling L0S
Feb 14 14:46:40 firefly kernel: [   97.349434] iwlwifi 0000:06:00.0: Radio type=0x0-0x2-0x0
Feb 14 14:46:40 firefly NetworkManager[1208]: <info> wake requested (sleeping: yes  enabled: yes)
Feb 14 14:46:40 firefly NetworkManager[1208]: <info> waking up and re-enabling...
Feb 14 14:46:40 firefly NetworkManager[1208]: <info> WWAN now enabled by management service
Feb 14 14:46:40 firefly NetworkManager[1208]: <info> (wlan0): now managed
Feb 14 14:46:40 firefly NetworkManager[1208]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Feb 14 14:46:40 firefly NetworkManager[1208]: <info> (wlan0): bringing up device.
Feb 14 14:46:40 firefly NetworkManager[1208]: NetworkManager[1208]: <info> wake requested (sleeping: yes  enabled: yes)
Feb 14 14:46:40 firefly NetworkManager[1208]: NetworkManager[1208]: <info> waking up and re-enabling...
Feb 14 14:46:40 firefly NetworkManager[1208]: NetworkManager[1208]: <info> WWAN now enabled by management service
Feb 14 14:46:40 firefly NetworkManager[1208]: NetworkManager[1208]: <info> (wlan0): now managed
Feb 14 14:46:40 firefly NetworkManager[1208]: NetworkManager[1208]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Feb 14 14:46:40 firefly NetworkManager[1208]: NetworkManager[1208]: <info> (wlan0): bringing up device.


On Mon, 2012-02-13 at 09:41 -0500, Chris Mason wrote:
> On Mon, Feb 13, 2012 at 07:47:39PM +0530, Srivatsa S. Bhat wrote:
> > Adding some Cc's.
> > 
> > On 02/12/2012 01:34 AM, Nathan A. Mourey II wrote:
> > 
> > > I just installed the new kernel with yum update.  I have an external eSATA hard drive that is 
> > > formatted with btrfs.  I closed the lid once it had booted up, I had not logged in yet.  Latter I opened
> > > the lid and had the following message on the screen.  Hope it helps.
> > > 
> > > 
> > > Feb 11 14:39:03 firefly kernel: [  253.236050] ------------[ cut here ]------------
> > > Feb 11 14:39:03 firefly kernel: [  253.236066] kernel BUG at fs/btrfs/transaction.c:1337!
> 
> This crash corresponds to:
> 
>         ret = btrfs_write_and_wait_transaction(trans, root);
>         BUG_ON(ret);
> 
> Which basically means we were not able to write all the metadata for the
> transaction (EIO during writeback).  Do other messages from the kernel
> tell you if the crash happened before or after the suspend?
> 
> What happened when the machine rebooted?
> 
> Since the drive is external, I'm going to guess this is related to the
> device going away at the wrong time.  Was it plugged in the whole time?
> 
> -chris

Download attachment "signature.asc" of type "application/pgp-signature" (837 bytes)

Powered by blists - more mailing lists