XFS: mount hangs for corrupted filesystem

[Rafael David Tinoco]

It was brought to my attention this situation:

--------
mount hangs at the following stack:
crash> bt 2882
PID: 2882 TASK: ffff88084e75c800 CPU: 7 COMMAND: "mount"
#0 [ffff880036a73b38] schedule at ffffffff8175e320
#1 [ffff880036a73bc0] xfs_ail_push_all_sync at ffffffffa02e5478 [xfs]
#2 [ffff880036a73c30] xfs_log_quiesce at ffffffffa02e0b67 [xfs]
#3 [ffff880036a73c50] xfs_log_unmount at ffffffffa02e0bb6 [xfs]
#4 [ffff880036a73c70] xfs_mountfs at ffffffffa029332a [xfs]
#5 [ffff880036a73ce0] xfs_fs_fill_super at ffffffffa0296707 [xfs]
#6 [ffff880036a73d20] mount_bdev at ffffffff811cd4a9
#7 [ffff880036a73db0] xfs_fs_mount at ffffffffa02946f5 [xfs]
#8 [ffff880036a73dc0] mount_fs at ffffffff811ce123
#9 [ffff880036a73e10] vfs_kern_mount at ffffffff811e9bf6
#10 [ffff880036a73e60] do_new_mount at ffffffff811eb3a4
#11 [ffff880036a73ec0] do_mount at ffffffff811ec706
#12 [ffff880036a73f20] sys_mount at ffffffff811ecad0
#13 [ffff880036a73f80] system_call_fastpath at ffffffff8176ae2d
RIP: 00007f2340eb6c2a RSP: 00007fff25675368 RFLAGS: 00010206
RAX: 00000000000000a5 RBX: ffffffff8176ae2d RCX: 0000000000000026
RDX: 0000000000b04c20 RSI: 0000000000b04bf0 RDI: 0000000000b04bd0
RBP: 00000000c0ed0400 R8: 0000000000b04c70 R9: 0000000000000001
R10: ffffffffc0ed0400 R11: 0000000000000202 R12: 0000000000b04bf0
R13: 0000000000b04b50 R14: 0000000000000400 R15: 0000000000000000
ORIG_RAX: 00000000000000a5 CS: 0033 SS: 002b

The corresponding disk is /dev/sdd1, any IO (xfs_check, etc) also hangs and had "D" state.

This reproducible with 3.11 and 3.13 kernel both.

The storage node is out of service because of this problem
--------

I'm still asking for more data (sosreport and kernel dump).

[Brad Figg (brad-figg)]

This bug is missing log files that will aid in diagnosing the problem. From a terminal window please run:

apport-collect 1382801

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Rafael David Tinoco (rafaeldtinoco)]

========
ANALYSIS
========

********
#0 [ffff880036a73b38] schedule at ffffffff8175e320
#1 [ffff880036a73bc0] xfs_ail_push_all_sync at ffffffffa02e5478 [xfs]
#2 [ffff880036a73c30] xfs_log_quiesce at ffffffffa02e0b67 [xfs]
#3 [ffff880036a73c50] xfs_log_unmount at ffffffffa02e0bb6 [xfs]
#4 [ffff880036a73c70] xfs_mountfs at ffffffffa029332a [xfs]

Analyzing the stack trace we can see that, during a xfs_fs_mount, the only
possible way to get into "xfs_log_unmount" is if the XFS filesystem is
CORRUPTED.

636 xfs_mountfs(
637 xfs_mount_t *mp)
638 {
639 xfs_sb_t *sbp = &(mp->m_sb);
640 xfs_inode_t *rip;
...
836 /*
837 * Get and sanity-check the root inode.
838 * Save the pointer to it in the mount structure.
839 */
840 error = xfs_iget(mp, NULL, sbp->sb_rootino, 0, XFS_ILOCK_EXCL, &rip);
841 if (error) {
842 xfs_warn(mp, "failed to read root inode");
843 goto out_log_dealloc;
844 }
845
...
955 out_log_dealloc:
956 xfs_log_unmount(mp);
...

So we DO KNOW your XFS is considered to be CORRUPTED (by XFS function
xfs_iget(), called for the root inode as a sanity check).
********

Either way, lets continue debugging to make sure we understand why XFS
didn't give us an error about the filesystem being corrupted:

Following the stack:

#2 [ffff880036a73c30] xfs_log_quiesce at ffffffffa02e0b67 [xfs]
#3 [ffff880036a73c50] xfs_log_unmount at ffffffffa02e0bb6 [xfs]

We can see that xfs_log_quiesce calls

#1 [ffff880036a73bc0] xfs_ail_push_all_sync at ffffffffa02e5478 [xfs]

The function responsible to push ALL *AIL structure into disk (for unmount
and freeze purposes).

This function has a simple code:

600 struct xfs_log_item *lip;
601 DEFINE_WAIT(wait);
602
603 spin_lock(&ailp->xa_lock);
604 while ((lip = xfs_ail_max(ailp)) != NULL) {
605 prepare_to_wait(&ailp->xa_empty, &wait, TASK_UNINTERRUPTIBLE);
606 ailp->xa_target = lip->li_lsn;
607 wake_up_process(ailp->xa_task);
608 spin_unlock(&ailp->xa_lock);
609 schedule();
610 spin_lock(&ailp->xa_lock);
611 }
612 spin_unlock(&ailp->xa_lock);
613
614 finish_wait(&ailp->xa_empty, &wait);

Where it gets all "xfs_log_items" from the AIL double linked list and
calls the function responsible to commit this "log items" into the disk:

607 wake_up_process(ailp->xa_task);

POSSIBLE XFS BUG:

XFS can be stuck inside this loop because of something happening on the
ail (xa_task) callback function (responsible to commit xfs log items).
And this, of course, makes the "mount" process to hang in the "UNINTE-
RRUPTIBLE state (since its not safe to let userland kill this process).

OBS: Waiting for the core file so I can stack-trace this XFS worker to check
wether it is hang and what are its causes.

OBS: If XFS is hang on mount, for a corrupted XFS filesystem, this behavior
is a bug since the "mount" command should have returned saying the
filesystem didn't pass on the root-inode sanity check.

Working on this...

[Rafael David Tinoco (rafaeldtinoco)]

Regarding the mount hang (and not what caused the corruption):

Im waiting for the following data:

## terminal 1

# apt-get install trace-cmd
# trace-cmd stop && trace-cmd reset
# trace-cmd record -e *xfs*

(it will expect for you to ctrl+c)

## terminal 2

# mount /dev/sdd1 (which i believe is the corrupted one)

## terminal 1 (after 5 seconds)

# trace-cmd report -i ./trace.dat | gzip > trace_xfs_ail.gz

--------------------

Idea here is this:

crash> set 2698
PID: 2698
COMMAND: "mount"
TASK: ffff88084f301800 [THREAD_INFO: ffff88104fe7c000]
CPU: 11
STATE: TASK_UNINTERRUPTIBLE|TASK_TRACED|EXIT_DEAD
crash> bt
PID: 2698 TASK: ffff88084f301800 CPU: 11 COMMAND: "mount"
#0 [ffff88104fe7db38] __schedule at ffffffff8175ded3
#1 [ffff88104fe7dbb0] schedule at ffffffff8175e349
#2 [ffff88104fe7dbc0] xfs_ail_push_all_sync at ffffffffa02f2478 [xfs]
#3 [ffff88104fe7dc30] xfs_log_quiesce at ffffffffa02edb67 [xfs]
#4 [ffff88104fe7dc50] xfs_log_unmount at ffffffffa02edbb6 [xfs]
#5 [ffff88104fe7dc70] xfs_mountfs at ffffffffa02a032a [xfs]
#6 [ffff88104fe7dce0] xfs_fs_fill_super at ffffffffa02a3707 [xfs]
#7 [ffff88104fe7dd20] mount_bdev at ffffffff811cd4a9
#8 [ffff88104fe7ddb0] xfs_fs_mount at ffffffffa02a16f5 [xfs]
#9 [ffff88104fe7ddc0] mount_fs at ffffffff811ce123
#10 [ffff88104fe7de10] vfs_kern_mount at ffffffff811e9bf6
#11 [ffff88104fe7de60] do_new_mount at ffffffff811eb3a4
#12 [ffff88104fe7dec0] do_mount at ffffffff811ec706
#13 [ffff88104fe7df20] sys_mount at ffffffff811ecad0
#14 [ffff88104fe7df80] system_call_fastpath at ffffffff8176ae2d
RIP: 00007fe6f5572c2a RSP: 00007fffcdb172c8 RFLAGS: 00010202
RAX: 00000000000000a5 RBX: ffffffff8176ae2d RCX: 0000000000000026
RDX: 0000000000645ae0 RSI: 0000000000645ab0 RDI: 0000000000645a90
RBP: 00000000c0ed0400 R8: 0000000000645b30 R9: 0000000000000001
R10: ffffffffc0ed0400 R11: 0000000000000202 R12: 0000000000645ab0
R13: 0000000000645a10 R14: 0000000000000400 R15: 0000000000000000
ORIG_RAX: 00000000000000a5 CS: 0033 SS: 002b

The mount is "hang" because xfs_ail_push_all_sync is not being able to flush
the "AIL" (intent log) from the journal. But xfs_ail_push_all_sync does not
do it by itself. It calls:

wake_up_process(ailp->xa_task);

xa_task here is one kernel thread called "xfsaild/<disk>":

758 int
759 xfs_trans_ail_init(
...
775 ailp->xa_task = kthread_run(xfsaild, ailp, "xfsaild/%s",
776 ailp->xa_mount->m_fsname);

So digging this kernel thread, responsible to commit intent logs:

crash> ps | grep saild
2354 2 3 ffff8808507fb000 IN 0.0 0 0 [xfsaild/sdb1]
2588 2 6 ffff88084717c800 IN 0.0 0 0 [xfsaild/sdh1]
2703 2 9 ffff881042250000 IN 0.0 0 0 [xfsaild/sdd1]

I can see that process 2703 is the one called. Analyzing its stack:

crash> bt
PID: 2703 TASK: ffff881042250000 CPU: 9 COMMAND: "xfsaild/sdd1"
#0 [ffff88103b72fd38] __schedule at ffffffff8175ded3
#1 [ffff88103b72fdb0] schedule at ffffffff8175e349
#2 [ffff88103b72fdc0] schedule_timeout at ffffffff8175d55d
#3 [ffff88103b72fe70] xfsaild at ffffffffa02f2238 [xfs]
#4 [ffff88103b72fec0] kthread at ffffffff8108fb59
#5 [ffff88103b72ff50] ret_from_fork at ffffffff8176ad7c

I can see that schedule is being called by "schedule_timeout"... So xfsaild
is rescheduling i...

[Rafael David Tinoco (rafaeldtinoco)]

Following situation might be the same one we are facing here:

http://t79525.file-systems-xfs-general.file-systemstalk.us/xfs-umount-hang-in-xfs-ail-push-all-sync-on-i-o-error-t79525.html

Where XFS is hang on umount (part of the mount stack trace when
filesystem is corrupted). It looks like upstream developers did not
go further with the investigation (May 2014) with the following
comment (after a trace output):

"""
What is happening is that the inodes in the buffer are already
marked as "being flushed" and hence the AIL does not push the inode
buffer again, and hence the IO completion callbacks on the buffer
that will remove the inodes from the AIL are never called. Not sure
how to fix this one yet....
"""

I'm expecting trace outputs from user so I can confirm we are
facing the same situation for this BUG.

Thank you

Rafael Tinoco

[Launchpad Janitor (janitor)]

[Expired for linux (Ubuntu) because there has been no activity for 60 days.]

[kirubakaran kaliannan (kirubak)]

The exact problem is see again. Ho do we reopen this issue back ?