* RE: Metadata corruption detected at xfs_attr3_leaf_write_verify [not found] <CAPh1sj5oU6QRyH_cnzrkGJb6ed3XO4fGABJ4yJLPnb-ppqVJeg@mail.gmail.com> @ 2017-07-21 13:31 ` Shyam Kaushik 2017-07-26 5:22 ` Metadata corruption at xfs_attr3_leaf_write_verify() Shyam Kaushik 1 sibling, 0 replies; 13+ messages in thread From: Shyam Kaushik @ 2017-07-21 13:31 UTC (permalink / raw) To: linux-xfs Hi Eric et al, I'am pulling from an old thread. From time to time we hit an xfs corruption when xattr leaf is attempted to be written when it has ichdr.count==0. We are on an old kernel 3.18.19. We managed to capture xfs trace buffer closer to the problem time. This is the corruption report Jul 20 05:22:27.189727 node1 kernel: [466290.765299] XFS (dm-78): Metadata corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 [xfs], block 0x9698734d8 Jul 20 05:22:27.189741 node1 kernel: [466290.767279] XFS (dm-78): Unmount and run xfs_repair Jul 20 05:22:27.189743 node1 kernel: [466290.768022] XFS (dm-78): First 64 bytes of corrupted metadata buffer: Jul 20 05:22:27.191635 node1 kernel: [466290.768832] ffff88002b4bf000: 00 00 00 00 00 00 00 00 fb ee 00 00 00 00 00 00 ................ Jul 20 05:22:27.192949 node1 kernel: [466290.770163] ffff88002b4bf010: 10 00 00 00 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... Jul 20 05:22:27.192953 node1 kernel: [466290.771264] ffff88002b4bf020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Jul 20 05:22:27.195921 node1 kernel: [466290.772815] ffff88002b4bf030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ >From xfs xattr debug trace, it appears that a file is created within a directory having default ACL set. This causes file creation to insert xattr leaf during file creation. This completes queuing an AIL. Immediately after this an explicit xfs_setattr is being done on the same file which alters the default ACL & this causes default ACL to be removed/added. It looks like this 2nd set attr is somehow influencing the first AIL entry that it is being seen with ichr.count==0 during the write. Any pointers/input to check this further is greatly appreciated. I can pass the full xfs debug trace if required. Here is the snippet of debug trace causing the issue <...>-18953 [004] ...1 466290.749358: xfs_attr_sf_create: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749359: xfs_attr_sf_addname: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749361: xfs_attr_sf_lookup: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749362: xfs_attr_sf_to_leaf: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749430: xfs_attr_leaf_create: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749454: xfs_attr_leaf_addname: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749456: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749457: xfs_attr_leaf_add: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749458: xfs_attr_leaf_add_work: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749649: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.749908: xfs_attr_leaf_get: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval 0xea9061c8 op_flags <...>-18953 [004] ...1 466290.749910: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval 0xea9061c8 op_flags <...>-18953 [004] ...1 466290.749918: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.749931: xfs_attr_leaf_get: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval 0x487716dd op_flags <...>-18953 [004] ...1 466290.749932: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval 0x487716dd op_flags <...>-18953 [004] ...1 466290.749984: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.749990: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750063: xfs_setattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750257: xfs_attr_leaf_addname: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750260: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750261: xfs_attr_leaf_replace: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750262: xfs_attr_leaf_add: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750262: xfs_attr_leaf_add_work: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750270: xfs_attr_leaf_flipflags: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750275: xfs_attr_leaf_remove: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750461: xfs_attr_leaf_removename: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 0 hashval 0xea9061c8 op_flags OKNOENT <...>-18953 [004] ...1 466290.750463: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 0 hashval 0xea9061c8 op_flags OKNOENT <...>-18953 [004] ...1 466290.750474: xfs_attr_leaf_addname: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval 0x487716dd op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750475: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval 0x487716dd op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750476: xfs_attr_leaf_add: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval 0x487716dd op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750476: xfs_attr_leaf_add_work: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval 0x487716dd op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750645: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750648: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750645: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750648: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750659: xfs_attr_leaf_get: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval 0x487716dd op_flags <...>-18953 [004] ...1 466290.750661: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval 0x487716dd op_flags <...>-18953 [004] ...1 466290.750744: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750791: xfs_attr_leaf_addname: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750793: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750794: xfs_attr_leaf_add: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750794: xfs_attr_leaf_add_work: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.751029: xfs_attr_leaf_get: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval 0xea9061c8 op_flags <...>-18953 [004] ...1 466290.751031: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval 0xea9061c8 op_flags Thanks. --Shyam On Tue, Apr 26, 2016 at 4:10 PM, Shyam Kaushik <shyam@zadarastorage.com> wrote: Hi Eric, Yes this is a non-CRC FS. The workload is we a custom application that does several (16 threads) file create/read/writes/update xattrs on a XFS mounted over raw disk. There is no messages prior to this & we hit this once in a few days (like every 4-5 days). I will try your suggestion of running with xfs_attr_* tracepoints all the time so that when we hit this error we have better info. Please let me know if you prefer to add further debug prints. Thanks. --Shyam > Eric Sandeen sandeen at sandeen.net wrote: > On Mon Apr 25 16:57:11 CDT 2016 > > Is this a non-crc filesystem? > > > XFS_ATTR_LEAF_MAGIC is ok (if it's a non-crc filesystem) > > Looks the same as the other report, tripping on: > > if (ichdr.count == 0) > return false; > > A reproducer would be super here. At least maybe a description of the > workload that hits it? > > Count is manipulated in things like attr leaf compaction... > Any other messages prior to this? > > How often do you hit it? > > You could also turn on xfs_attr_* tracepoints, maybe. > > -Eric -----Original Message----- From: Shyam Kaushik [mailto:shyam@zadarastorage.com] Sent: 25 April 2016 22:22 To: 'xfs@oss.sgi.com' Cc: Alex Lyakas Subject: Metadata corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 Hi Dave et al, We are periodically hitting the below metadata corruption with XFS over a raw disk running several file copies with xattr operations on kernel 3.18.19. Unmounting & running xfs_repair doesn't report any corruption. I see that this was last reported here http://oss.sgi.com/archives/xfs/2015-12/msg00224.html Unfortunately we dont have a reproducer, but this issue happens periodically. We can add more debug prints & allow this issue to happen again. Can you pls suggest any options to debug this further? Thanks Apr 20 21:58:03 node1 kernel: [16736.286370] XFS (dm-26): Metadata corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 [xfs], block 0x19c5c728 Apr 20 21:58:03 node1 kernel: [16736.289084] XFS (dm-26): Unmount and run xfs_repair Apr 20 21:58:03 node1 kernel: [16736.290257] XFS (dm-26): First 64 bytes of corrupted metadata buffer: Apr 20 21:58:03 node1 kernel: [16736.291797] ffff880123668000: 00 00 00 00 00 00 00 00 fb ee 00 00 00 00 00 00 ................ Apr 20 21:58:03 node1 kernel: [16736.293823] ffff880123668010: 10 00 00 00 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... Apr 20 21:58:03 node1 kernel: [16736.297504] ffff880123668020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Apr 20 21:58:03 node1 kernel: [16736.299343] ffff880123668030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Apr 20 21:58:03 node1 kernel: [16736.301465] XFS (dm-26): xfs_do_force_shutdown(0x8) called from line 1244 of file fs/xfs/xfs_buf.c. Return address = 0xffffffffc095cee0 Apr 20 21:58:03 node1 kernel: [16736.301469] ------------[ cut here ]------------ Apr 20 21:58:03 node1 kernel: [16736.301551] XFS(dm-26): SHUTDOWN!!! old_flags=0x0 new_flags=0x8 Apr 20 21:58:03 node1 kernel: [16736.301703] CPU: 1 PID: 7857 Comm: xfsaild/dm-26 Tainted: G OE 3.18.19 #1 Apr 20 21:58:03 node1 kernel: [16736.301705] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 Apr 20 21:58:03 node1 kernel: [16736.301707] 0000000000000009 ffff88020c5ffb38 ffffffff81710c85 0000000000000000 Apr 20 21:58:03 node1 kernel: [16736.301711] ffff88020c5ffb88 ffff88020c5ffb78 ffffffff81072df1 2e2e202030302030 Apr 20 21:58:03 node1 kernel: [16736.301715] 0000000000000000 0000000000000008 ffff88020c127000 0000000000000000 Apr 20 21:58:03 node1 kernel: [16736.301718] Call Trace: Apr 20 21:58:03 node1 kernel: [16736.301769] [<ffffffff81710c85>] dump_stack+0x4e/0x71 Apr 20 21:58:03 node1 kernel: [16736.301780] [<ffffffff81072df1>] warn_slowpath_common+0x81/0xa0 Apr 20 21:58:03 node1 kernel: [16736.301784] [<ffffffff81072e56>] warn_slowpath_fmt+0x46/0x50 Apr 20 21:58:03 node1 kernel: [16736.301860] [<ffffffffc09693f3>] xfs_do_force_shutdown+0x33/0x170 [xfs] Apr 20 21:58:03 node1 kernel: [16736.301921] [<ffffffffc095cee0>] ? _xfs_buf_ioapply+0xa0/0x430 [xfs] Apr 20 21:58:03 node1 kernel: [16736.301951] [<ffffffffc095ee4b>] ? __xfs_buf_delwri_submit+0x22b/0x290 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302066] [<ffffffffc095cee0>] _xfs_buf_ioapply+0xa0/0x430 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302137] [<ffffffff8109e260>] ? wake_up_state+0x20/0x20 Apr 20 21:58:03 node1 kernel: [16736.302162] [<ffffffffc095ee4b>] ? __xfs_buf_delwri_submit+0x22b/0x290 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302183] [<ffffffffc095ea78>] xfs_buf_submit+0x68/0x210 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302241] [<ffffffffc095ee4b>] __xfs_buf_delwri_submit+0x22b/0x290 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302267] [<ffffffffc095fc60>] ? xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302291] [<ffffffffc098f440>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302308] [<ffffffffc095fc60>] xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302333] [<ffffffffc098f66b>] xfsaild+0x22b/0x630 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302513] [<ffffffffc098f440>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302518] [<ffffffff810911b9>] kthread+0xc9/0xe0 Apr 20 21:58:03 node1 kernel: [16736.302522] [<ffffffff810910f0>] ? kthread_create_on_node+0x180/0x180 Apr 20 21:58:03 node1 kernel: [16736.302530] [<ffffffff81717918>] ret_from_fork+0x58/0x90 Apr 20 21:58:03 node1 kernel: [16736.302549] [<ffffffff810910f0>] ? kthread_create_on_node+0x180/0x180 Apr 20 21:58:03 node1 kernel: [16736.302551] ---[ end trace 0bb81b88fdd6a298 ]--- --Shyam ^ permalink raw reply [flat|nested] 13+ messages in thread
* Metadata corruption at xfs_attr3_leaf_write_verify() [not found] <CAPh1sj5oU6QRyH_cnzrkGJb6ed3XO4fGABJ4yJLPnb-ppqVJeg@mail.gmail.com> 2017-07-21 13:31 ` Metadata corruption detected at xfs_attr3_leaf_write_verify Shyam Kaushik @ 2017-07-26 5:22 ` Shyam Kaushik 2017-07-26 12:15 ` Brian Foster 1 sibling, 1 reply; 13+ messages in thread From: Shyam Kaushik @ 2017-07-26 5:22 UTC (permalink / raw) To: dchinner, Dave Chinner; +Cc: linux-xfs Hi Dave, >From time to time we hit an xfs corruption when xattr leaf is attempted to be written when it has ichdr.count==0. We are on an old kernel 3.18.19. We managed to capture xfs trace buffer closer to the problem time. This is the corruption report Jul 20 05:22:27.189727 node1 kernel: [466290.765299] XFS (dm-78): Metadata corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 [xfs], block 0x9698734d8 Jul 20 05:22:27.189741 node1 kernel: [466290.767279] XFS (dm-78): Unmount and run xfs_repair Jul 20 05:22:27.189743 node1 kernel: [466290.768022] XFS (dm-78): First 64 bytes of corrupted metadata buffer: Jul 20 05:22:27.191635 node1 kernel: [466290.768832] ffff88002b4bf000: 00 00 00 00 00 00 00 00 fb ee 00 00 00 00 00 00 ................ Jul 20 05:22:27.192949 node1 kernel: [466290.770163] ffff88002b4bf010: 10 00 00 00 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... Jul 20 05:22:27.192953 node1 kernel: [466290.771264] ffff88002b4bf020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Jul 20 05:22:27.195921 node1 kernel: [466290.772815] ffff88002b4bf030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ >From xfs xattr debug trace, it appears that a file is created within a directory having default ACL set. This causes file creation to insert xattr leaf during file creation. This completes queuing an AIL. Immediately after this an explicit xfs_setattr is being done on the same file which alters the default ACL & this causes default ACL to be removed/added. It looks like this 2nd set attr is somehow influencing the first AIL entry that it is being seen with ichr.count==0 during the write. I can pass the full xfs debug trace if required. Here is the snippet of debug trace causing the issue <...>-18953 [004] ...1 466290.749358: xfs_attr_sf_create: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749359: xfs_attr_sf_addname: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749361: xfs_attr_sf_lookup: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749362: xfs_attr_sf_to_leaf: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749430: xfs_attr_leaf_create: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749454: xfs_attr_leaf_addname: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749456: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749457: xfs_attr_leaf_add: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749458: xfs_attr_leaf_add_work: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.749649: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.749908: xfs_attr_leaf_get: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval 0xea9061c8 op_flags <...>-18953 [004] ...1 466290.749910: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval 0xea9061c8 op_flags <...>-18953 [004] ...1 466290.749918: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.749931: xfs_attr_leaf_get: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval 0x487716dd op_flags <...>-18953 [004] ...1 466290.749932: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval 0x487716dd op_flags <...>-18953 [004] ...1 466290.749984: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.749990: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750063: xfs_setattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750257: xfs_attr_leaf_addname: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750260: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750261: xfs_attr_leaf_replace: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750262: xfs_attr_leaf_add: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750262: xfs_attr_leaf_add_work: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750270: xfs_attr_leaf_flipflags: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750275: xfs_attr_leaf_remove: dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750461: xfs_attr_leaf_removename: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 0 hashval 0xea9061c8 op_flags OKNOENT <...>-18953 [004] ...1 466290.750463: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 0 hashval 0xea9061c8 op_flags OKNOENT <...>-18953 [004] ...1 466290.750474: xfs_attr_leaf_addname: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval 0x487716dd op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750475: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval 0x487716dd op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750476: xfs_attr_leaf_add: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval 0x487716dd op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750476: xfs_attr_leaf_add_work: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval 0x487716dd op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750645: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750648: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750645: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750648: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750659: xfs_attr_leaf_get: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval 0x487716dd op_flags <...>-18953 [004] ...1 466290.750661: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval 0x487716dd op_flags <...>-18953 [004] ...1 466290.750744: xfs_getattr: dev 253:78 ino 0x1749833903 <...>-18953 [004] ...1 466290.750791: xfs_attr_leaf_addname: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750793: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750794: xfs_attr_leaf_add: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.750794: xfs_attr_leaf_add_work: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 op_flags ADDNAME|OKNOENT <...>-18953 [004] ...1 466290.751029: xfs_attr_leaf_get: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval 0xea9061c8 op_flags <...>-18953 [004] ...1 466290.751031: xfs_attr_leaf_lookup: dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval 0xea9061c8 op_flags Any pointers/input to check this further is greatly appreciated! Thanks. --Shyam On Tue, Apr 26, 2016 at 4:10 PM, Shyam Kaushik <shyam@zadarastorage.com> wrote: Hi Eric, Yes this is a non-CRC FS. The workload is we a custom application that does several (16 threads) file create/read/writes/update xattrs on a XFS mounted over raw disk. There is no messages prior to this & we hit this once in a few days (like every 4-5 days). I will try your suggestion of running with xfs_attr_* tracepoints all the time so that when we hit this error we have better info. Please let me know if you prefer to add further debug prints. Thanks. --Shyam > Eric Sandeen sandeen at sandeen.net wrote: > On Mon Apr 25 16:57:11 CDT 2016 > > Is this a non-crc filesystem? > > > XFS_ATTR_LEAF_MAGIC is ok (if it's a non-crc filesystem) > > Looks the same as the other report, tripping on: > > if (ichdr.count == 0) > return false; > > A reproducer would be super here. At least maybe a description of the > workload that hits it? > > Count is manipulated in things like attr leaf compaction... > Any other messages prior to this? > > How often do you hit it? > > You could also turn on xfs_attr_* tracepoints, maybe. > > -Eric -----Original Message----- From: Shyam Kaushik [mailto:shyam@zadarastorage.com] Sent: 25 April 2016 22:22 To: 'xfs@oss.sgi.com' Cc: Alex Lyakas Subject: Metadata corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 Hi Dave et al, We are periodically hitting the below metadata corruption with XFS over a raw disk running several file copies with xattr operations on kernel 3.18.19. Unmounting & running xfs_repair doesn't report any corruption. I see that this was last reported here http://oss.sgi.com/archives/xfs/2015-12/msg00224.html Unfortunately we dont have a reproducer, but this issue happens periodically. We can add more debug prints & allow this issue to happen again. Can you pls suggest any options to debug this further? Thanks Apr 20 21:58:03 node1 kernel: [16736.286370] XFS (dm-26): Metadata corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 [xfs], block 0x19c5c728 Apr 20 21:58:03 node1 kernel: [16736.289084] XFS (dm-26): Unmount and run xfs_repair Apr 20 21:58:03 node1 kernel: [16736.290257] XFS (dm-26): First 64 bytes of corrupted metadata buffer: Apr 20 21:58:03 node1 kernel: [16736.291797] ffff880123668000: 00 00 00 00 00 00 00 00 fb ee 00 00 00 00 00 00 ................ Apr 20 21:58:03 node1 kernel: [16736.293823] ffff880123668010: 10 00 00 00 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... Apr 20 21:58:03 node1 kernel: [16736.297504] ffff880123668020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Apr 20 21:58:03 node1 kernel: [16736.299343] ffff880123668030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Apr 20 21:58:03 node1 kernel: [16736.301465] XFS (dm-26): xfs_do_force_shutdown(0x8) called from line 1244 of file fs/xfs/xfs_buf.c. Return address = 0xffffffffc095cee0 Apr 20 21:58:03 node1 kernel: [16736.301469] ------------[ cut here ]------------ Apr 20 21:58:03 node1 kernel: [16736.301551] XFS(dm-26): SHUTDOWN!!! old_flags=0x0 new_flags=0x8 Apr 20 21:58:03 node1 kernel: [16736.301703] CPU: 1 PID: 7857 Comm: xfsaild/dm-26 Tainted: G OE 3.18.19 #1 Apr 20 21:58:03 node1 kernel: [16736.301705] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 Apr 20 21:58:03 node1 kernel: [16736.301707] 0000000000000009 ffff88020c5ffb38 ffffffff81710c85 0000000000000000 Apr 20 21:58:03 node1 kernel: [16736.301711] ffff88020c5ffb88 ffff88020c5ffb78 ffffffff81072df1 2e2e202030302030 Apr 20 21:58:03 node1 kernel: [16736.301715] 0000000000000000 0000000000000008 ffff88020c127000 0000000000000000 Apr 20 21:58:03 node1 kernel: [16736.301718] Call Trace: Apr 20 21:58:03 node1 kernel: [16736.301769] [<ffffffff81710c85>] dump_stack+0x4e/0x71 Apr 20 21:58:03 node1 kernel: [16736.301780] [<ffffffff81072df1>] warn_slowpath_common+0x81/0xa0 Apr 20 21:58:03 node1 kernel: [16736.301784] [<ffffffff81072e56>] warn_slowpath_fmt+0x46/0x50 Apr 20 21:58:03 node1 kernel: [16736.301860] [<ffffffffc09693f3>] xfs_do_force_shutdown+0x33/0x170 [xfs] Apr 20 21:58:03 node1 kernel: [16736.301921] [<ffffffffc095cee0>] ? _xfs_buf_ioapply+0xa0/0x430 [xfs] Apr 20 21:58:03 node1 kernel: [16736.301951] [<ffffffffc095ee4b>] ? __xfs_buf_delwri_submit+0x22b/0x290 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302066] [<ffffffffc095cee0>] _xfs_buf_ioapply+0xa0/0x430 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302137] [<ffffffff8109e260>] ? wake_up_state+0x20/0x20 Apr 20 21:58:03 node1 kernel: [16736.302162] [<ffffffffc095ee4b>] ? __xfs_buf_delwri_submit+0x22b/0x290 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302183] [<ffffffffc095ea78>] xfs_buf_submit+0x68/0x210 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302241] [<ffffffffc095ee4b>] __xfs_buf_delwri_submit+0x22b/0x290 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302267] [<ffffffffc095fc60>] ? xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302291] [<ffffffffc098f440>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302308] [<ffffffffc095fc60>] xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302333] [<ffffffffc098f66b>] xfsaild+0x22b/0x630 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302513] [<ffffffffc098f440>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs] Apr 20 21:58:03 node1 kernel: [16736.302518] [<ffffffff810911b9>] kthread+0xc9/0xe0 Apr 20 21:58:03 node1 kernel: [16736.302522] [<ffffffff810910f0>] ? kthread_create_on_node+0x180/0x180 Apr 20 21:58:03 node1 kernel: [16736.302530] [<ffffffff81717918>] ret_from_fork+0x58/0x90 Apr 20 21:58:03 node1 kernel: [16736.302549] [<ffffffff810910f0>] ? kthread_create_on_node+0x180/0x180 Apr 20 21:58:03 node1 kernel: [16736.302551] ---[ end trace 0bb81b88fdd6a298 ]--- --Shyam ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-07-26 5:22 ` Metadata corruption at xfs_attr3_leaf_write_verify() Shyam Kaushik @ 2017-07-26 12:15 ` Brian Foster 0 siblings, 0 replies; 13+ messages in thread From: Brian Foster @ 2017-07-26 12:15 UTC (permalink / raw) To: Shyam Kaushik; +Cc: dchinner, Dave Chinner, linux-xfs On Wed, Jul 26, 2017 at 10:52:50AM +0530, Shyam Kaushik wrote: > Hi Dave, > > From time to time we hit an xfs corruption when xattr leaf is attempted to > be written when it has ichdr.count==0. > > We are on an old kernel 3.18.19. We managed to capture xfs trace buffer > closer to the problem time. > > This is the corruption report > Jul 20 05:22:27.189727 node1 kernel: [466290.765299] XFS (dm-78): Metadata > corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 [xfs], block > 0x9698734d8 > Jul 20 05:22:27.189741 node1 kernel: [466290.767279] XFS (dm-78): Unmount > and run xfs_repair > Jul 20 05:22:27.189743 node1 kernel: [466290.768022] XFS (dm-78): First 64 > bytes of corrupted metadata buffer: > Jul 20 05:22:27.191635 node1 kernel: [466290.768832] ffff88002b4bf000: 00 > 00 00 00 00 00 00 00 fb ee 00 00 00 00 00 00 ................ > Jul 20 05:22:27.192949 node1 kernel: [466290.770163] ffff88002b4bf010: 10 > 00 00 00 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... > Jul 20 05:22:27.192953 node1 kernel: [466290.771264] ffff88002b4bf020: 00 > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ > Jul 20 05:22:27.195921 node1 kernel: [466290.772815] ffff88002b4bf030: 00 > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ > > From xfs xattr debug trace, it appears that a file is created within a > directory having default ACL set. This causes file creation to insert xattr > leaf during file creation. This completes queuing an AIL. Immediately after > this an explicit xfs_setattr is being done on the same file which alters the > default ACL & this causes default ACL to be removed/added. It looks like > this 2nd set attr is somehow influencing the first AIL entry that it is > being seen with ichr.count==0 during the write. > I didn't notice anything on a quick pass through the code that would lead to this situation. It looks to me that the initial attr creates the leaf (where count is initialized to 0), but then adds the xattr in the same transaction (which should bump ichdr.count). The next set of SGI_ACL_FILE calls xfs_attr_leaf_add[_work]() before it rolls the transaction, which looks like it should bump ichdr.count again before we flip the inactive flags and remove the old attr. The output above clearly shows ichdr.count == 0, so I could easily be missing something or something else could be going on here. Unless somebody else chimes in with something more concrete, could you add a trace_printk() statement to xfs_attr3_leaf_verify() at the appropriate point where the verifier fails and re-collect the above tracepoint data? You could print out bp->b_bno just so we can correspond the log message to the tracepoint, but otherwise I'm just more curious to see where in the sequence of the xattr replace that the verifier happens to trigger and fail. Note that when you enable the attr tracepoints, you may have to include '-e print' to make sure the trace_printk() is enabled as well. E.g., something like 'trace-cmd start -e xfs:xfs_attr_* -e print' should work. Brian > I can pass the full xfs debug trace if required. Here is the snippet of > debug trace causing the issue > > <...>-18953 [004] ...1 466290.749358: xfs_attr_sf_create: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749359: xfs_attr_sf_addname: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749361: xfs_attr_sf_lookup: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749362: xfs_attr_sf_to_leaf: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749430: xfs_attr_leaf_create: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749454: xfs_attr_leaf_addname: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749456: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749457: xfs_attr_leaf_add: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749458: xfs_attr_leaf_add_work: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749649: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.749908: xfs_attr_leaf_get: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval > 0xea9061c8 op_flags > <...>-18953 [004] ...1 466290.749910: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval > 0xea9061c8 op_flags > <...>-18953 [004] ...1 466290.749918: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.749931: xfs_attr_leaf_get: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval > 0x487716dd op_flags > <...>-18953 [004] ...1 466290.749932: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval > 0x487716dd op_flags > <...>-18953 [004] ...1 466290.749984: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.749990: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750063: xfs_setattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750257: xfs_attr_leaf_addname: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750260: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750261: xfs_attr_leaf_replace: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750262: xfs_attr_leaf_add: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750262: xfs_attr_leaf_add_work: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750270: xfs_attr_leaf_flipflags: > dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 > hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750275: xfs_attr_leaf_remove: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750461: xfs_attr_leaf_removename: > dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 0 hashval > 0xea9061c8 op_flags OKNOENT > <...>-18953 [004] ...1 466290.750463: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 0 hashval 0xea9061c8 > op_flags OKNOENT > <...>-18953 [004] ...1 466290.750474: xfs_attr_leaf_addname: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval > 0x487716dd op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750475: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval > 0x487716dd op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750476: xfs_attr_leaf_add: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval > 0x487716dd op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750476: xfs_attr_leaf_add_work: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval > 0x487716dd op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750645: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750648: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750645: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750648: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750659: xfs_attr_leaf_get: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval > 0x487716dd op_flags > <...>-18953 [004] ...1 466290.750661: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval > 0x487716dd op_flags > <...>-18953 [004] ...1 466290.750744: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750791: xfs_attr_leaf_addname: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 > op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750793: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 > op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750794: xfs_attr_leaf_add: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 > op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750794: xfs_attr_leaf_add_work: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 > op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.751029: xfs_attr_leaf_get: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval > 0xea9061c8 op_flags > <...>-18953 [004] ...1 466290.751031: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval > 0xea9061c8 op_flags > > > Any pointers/input to check this further is greatly appreciated! Thanks. > > --Shyam > > On Tue, Apr 26, 2016 at 4:10 PM, Shyam Kaushik <shyam@zadarastorage.com> > wrote: > Hi Eric, > > Yes this is a non-CRC FS. The workload is we a custom application that > does several (16 threads) file create/read/writes/update xattrs on a XFS > mounted over raw disk. > > There is no messages prior to this & we hit this once in a few days (like > every 4-5 days). I will try your suggestion of running with xfs_attr_* > tracepoints all the time so that when we hit this error we have better > info. Please let me know if you prefer to add further debug prints. > Thanks. > > --Shyam > > > Eric Sandeen sandeen at sandeen.net wrote: > > On Mon Apr 25 16:57:11 CDT 2016 > > > > Is this a non-crc filesystem? > > > > > > XFS_ATTR_LEAF_MAGIC is ok (if it's a non-crc filesystem) > > > > Looks the same as the other report, tripping on: > > > > if (ichdr.count == 0) > > return false; > > > > A reproducer would be super here. At least maybe a description of the > > workload that hits it? > > > > Count is manipulated in things like attr leaf compaction... > > Any other messages prior to this? > > > > How often do you hit it? > > > > You could also turn on xfs_attr_* tracepoints, maybe. > > > > -Eric > > -----Original Message----- > From: Shyam Kaushik [mailto:shyam@zadarastorage.com] > Sent: 25 April 2016 22:22 > To: 'xfs@oss.sgi.com' > Cc: Alex Lyakas > Subject: Metadata corruption detected at > xfs_attr3_leaf_write_verify+0xe5/0x100 > > Hi Dave et al, > > We are periodically hitting the below metadata corruption with XFS over a > raw disk running several file copies with xattr operations on kernel > 3.18.19. Unmounting & running xfs_repair doesn't report any corruption. I > see that this was last reported here > http://oss.sgi.com/archives/xfs/2015-12/msg00224.html > > Unfortunately we dont have a reproducer, but this issue happens > periodically. We can add more debug prints & allow this issue to happen > again. Can you pls suggest any options to debug this further? Thanks > > Apr 20 21:58:03 node1 kernel: [16736.286370] XFS (dm-26): Metadata > corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 [xfs], block > 0x19c5c728 > Apr 20 21:58:03 node1 kernel: [16736.289084] XFS (dm-26): Unmount and run > xfs_repair > Apr 20 21:58:03 node1 kernel: [16736.290257] XFS (dm-26): First 64 bytes > of corrupted metadata buffer: > Apr 20 21:58:03 node1 kernel: [16736.291797] ffff880123668000: 00 00 00 00 > 00 00 00 00 fb ee 00 00 00 00 00 00 ................ > Apr 20 21:58:03 node1 kernel: [16736.293823] ffff880123668010: 10 00 00 00 > 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... > Apr 20 21:58:03 node1 kernel: [16736.297504] ffff880123668020: 00 00 00 00 > 00 00 00 00 00 00 00 00 00 00 00 00 ................ > Apr 20 21:58:03 node1 kernel: [16736.299343] ffff880123668030: 00 00 00 00 > 00 00 00 00 00 00 00 00 00 00 00 00 ................ > Apr 20 21:58:03 node1 kernel: [16736.301465] XFS (dm-26): > xfs_do_force_shutdown(0x8) called from line 1244 of file fs/xfs/xfs_buf.c. > Return address = 0xffffffffc095cee0 > Apr 20 21:58:03 node1 kernel: [16736.301469] ------------[ cut here > ]------------ > Apr 20 21:58:03 node1 kernel: [16736.301551] XFS(dm-26): SHUTDOWN!!! > old_flags=0x0 new_flags=0x8 > Apr 20 21:58:03 node1 kernel: [16736.301703] CPU: 1 PID: 7857 Comm: > xfsaild/dm-26 Tainted: G OE 3.18.19 #1 > Apr 20 21:58:03 node1 kernel: [16736.301705] Hardware name: Bochs Bochs, > BIOS Bochs 01/01/2011 > Apr 20 21:58:03 node1 kernel: [16736.301707] 0000000000000009 > ffff88020c5ffb38 ffffffff81710c85 0000000000000000 > Apr 20 21:58:03 node1 kernel: [16736.301711] ffff88020c5ffb88 > ffff88020c5ffb78 ffffffff81072df1 2e2e202030302030 > Apr 20 21:58:03 node1 kernel: [16736.301715] 0000000000000000 > 0000000000000008 ffff88020c127000 0000000000000000 > Apr 20 21:58:03 node1 kernel: [16736.301718] Call Trace: > Apr 20 21:58:03 node1 kernel: [16736.301769] [<ffffffff81710c85>] > dump_stack+0x4e/0x71 > Apr 20 21:58:03 node1 kernel: [16736.301780] [<ffffffff81072df1>] > warn_slowpath_common+0x81/0xa0 > Apr 20 21:58:03 node1 kernel: [16736.301784] [<ffffffff81072e56>] > warn_slowpath_fmt+0x46/0x50 > Apr 20 21:58:03 node1 kernel: [16736.301860] [<ffffffffc09693f3>] > xfs_do_force_shutdown+0x33/0x170 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.301921] [<ffffffffc095cee0>] ? > _xfs_buf_ioapply+0xa0/0x430 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.301951] [<ffffffffc095ee4b>] ? > __xfs_buf_delwri_submit+0x22b/0x290 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302066] [<ffffffffc095cee0>] > _xfs_buf_ioapply+0xa0/0x430 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302137] [<ffffffff8109e260>] ? > wake_up_state+0x20/0x20 > Apr 20 21:58:03 node1 kernel: [16736.302162] [<ffffffffc095ee4b>] ? > __xfs_buf_delwri_submit+0x22b/0x290 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302183] [<ffffffffc095ea78>] > xfs_buf_submit+0x68/0x210 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302241] [<ffffffffc095ee4b>] > __xfs_buf_delwri_submit+0x22b/0x290 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302267] [<ffffffffc095fc60>] ? > xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302291] [<ffffffffc098f440>] ? > xfs_trans_ail_cursor_first+0x90/0x90 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302308] [<ffffffffc095fc60>] > xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302333] [<ffffffffc098f66b>] > xfsaild+0x22b/0x630 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302513] [<ffffffffc098f440>] ? > xfs_trans_ail_cursor_first+0x90/0x90 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302518] [<ffffffff810911b9>] > kthread+0xc9/0xe0 > Apr 20 21:58:03 node1 kernel: [16736.302522] [<ffffffff810910f0>] ? > kthread_create_on_node+0x180/0x180 > Apr 20 21:58:03 node1 kernel: [16736.302530] [<ffffffff81717918>] > ret_from_fork+0x58/0x90 > Apr 20 21:58:03 node1 kernel: [16736.302549] [<ffffffff810910f0>] ? > kthread_create_on_node+0x180/0x180 > Apr 20 21:58:03 node1 kernel: [16736.302551] ---[ end trace > 0bb81b88fdd6a298 ]--- > > --Shyam > -- > To unsubscribe from this list: send the line "unsubscribe linux-xfs" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 13+ messages in thread
[parent not found: <d161b07cad6536b0baf285328cf99500@mail.gmail.com>]
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() [not found] <d161b07cad6536b0baf285328cf99500@mail.gmail.com> @ 2017-08-01 17:30 ` Alex Lyakas 2017-08-01 18:22 ` Eric Sandeen 2017-08-01 23:18 ` Dave Chinner 0 siblings, 2 replies; 13+ messages in thread From: Alex Lyakas @ 2017-08-01 17:30 UTC (permalink / raw) To: linux-xfs; +Cc: Shyam Kaushik, bfoster, dchinner, david Greetings XFS developers, David, Brian, We did additional debugging on this issue. The problematic flow happens to be the following: - New inode (regular file) is being created. - As part of creation, due to parent directory having a default ACL, initial ACL is applied to the inode. - This ACL is applied as an extended attribute with name "SGI_ACL_FILE" and value length of 100 bytes. - XFS tries to add this attribute into the inline inode attribute fork area (AKA shortform). - But 100 bytes is too large for the shortform, so XFS creates an empty shortform and then calls xfs_attr_shortform_to_leaf() - This calls xfs_attr3_leaf_create() and creates a leaf with zero attributes. - Before XFS is able to add the attribute to the leaf, the xfsaild thread wants to write this leaf to disk, and trips over the assert in xfs_attr3_leaf_verify, that ichdr.count should not be 0 So this seems like a race condition, where xfsaild writes a not-fully-prepared xfs_buf to disk. To my understanding this can lead to different kinds of corruptions. Proof: We added prints in various places to catch this problem. Below [1] is the part of the kernel log that shows the problem. The relevant inode is 111236446948, and the relevant xfs_buf->b_bn is 0x1156aacf60. Thread 17576 is the one that wants to add a first attribute to an empty leaf. Thread 13689 is the one that wants to write the xfs_buf prematurely. Kernel is 3.18.19. Thanks, Alex. [1] Aug 1 10:44:23.787897 vsa-0000000a-vc-0 kernel: [177522.830217] [17576][at]xfs [xfs_attr_shortform_to_leaf:687] XFS(dm-79): ino[111236446948] SHORTFORM-TO-LEAF count=0 Aug 1 10:44:23.788035 vsa-0000000a-vc-0 kernel: [177522.830328] [25402][at]xfs [xfs_attr_remove:432] XFS(dm-79): ino[111236446947] xfs_attr_remove(NTACL) Aug 1 10:44:23.788038 vsa-0000000a-vc-0 kernel: [177522.830344] [25402][at]xfs [xfs_attr_leaf_addname:653] XFS(dm-79): ino[111236446947] bp[0x1156aa1770] ADD [SAMBA_PAI] xfs_attr3_leaf_add() Aug 1 10:44:23.788039 vsa-0000000a-vc-0 kernel: [177522.830346] [25402][at]xfs [xfs_attr3_leaf_add:1134] XFS(dm-79): ino[111236446947] bp[0x1156aa1770] LEAF ADD [SAMBA_PAI:\x02\x04€\b] Aug 1 10:44:23.788040 vsa-0000000a-vc-0 kernel: [177522.830348] [25402][at]xfs [xfs_attr3_leaf_add:1194] XFS(dm-79): ino[111236446947] bp[0x1156aa1770] LEAF ADD [SAMBA_PAI:\x02\x04€\b] leaf.count=2 Aug 1 10:44:23.788040 vsa-0000000a-vc-0 kernel: [177522.830386] [17576][at]xfs [xfs_attr3_leaf_create:1004] XFS(dm-79): ino[111236446948] bp[0x1156aacf60] NEW LEAF Aug 1 10:44:23.788041 vsa-0000000a-vc-0 kernel: [177522.830391] [17576][at]xfs [xfs_attr_shortform_to_leaf:757] XFS(dm-79): ino[111236446948] bp[0x1156aacf60] SHORTFORM-TO-LEAF leaf.count=0 Aug 1 10:44:23.788635 vsa-0000000a-vc-0 kernel: [177522.830780] [25402][at]xfs [xfs_attr_leaf_addname:653] XFS(dm-79): ino[111236446947] bp[0x1156aa1770] ADD [NTACL] xfs_attr3_leaf_add() Aug 1 10:44:23.788641 vsa-0000000a-vc-0 kernel: [177522.830783] [25402][at]xfs [xfs_attr3_leaf_add:1134] XFS(dm-79): ino[111236446947] bp[0x1156aa1770] LEAF ADD [NTACL:\x04] Aug 1 10:44:23.788642 vsa-0000000a-vc-0 kernel: [177522.830785] [25402][at]xfs [xfs_attr3_leaf_add:1194] XFS(dm-79): ino[111236446947] bp[0x1156aa1770] LEAF ADD [NTACL:\x04] leaf.count=3 Aug 1 10:44:23.794652 vsa-0000000a-vc-0 kernel: [177522.836690] [14069][at]xfs [xfs_attr_leaf_addname:653] XFS(dm-79): ino[147144507861] bp[0x1121416a48] ADD [SGI_ACL_FILE] xfs_attr3_leaf_add() Aug 1 10:44:23.794666 vsa-0000000a-vc-0 kernel: [177522.836697] [14069][at]xfs [xfs_attr3_leaf_add:1134] XFS(dm-79): ino[147144507861] bp[0x1121416a48] LEAF ADD [SGI_ACL_FILE:] Aug 1 10:44:23.794667 vsa-0000000a-vc-0 kernel: [177522.836702] [14069][at]xfs [xfs_attr3_leaf_add:1194] XFS(dm-79): ino[147144507861] bp[0x1121416a48] LEAF ADD [SGI_ACL_FILE:] leaf.count=2 Aug 1 10:44:23.794669 vsa-0000000a-vc-0 kernel: [177522.836709] [14069][at]xfs [xfs_attr_leaf_addname:731] XFS(dm-79): ino[147144507861] ADD [SGI_ACL_FILE] XFS_DA_OP_RENAME=>xfs_attr3_leaf_flipflags() Aug 1 10:44:23.794670 vsa-0000000a-vc-0 kernel: [177522.836715] [14069][at]xfs [xfs_attr_leaf_addname:765] XFS(dm-79): ino[147144507861] bp[0x1121416a48] ADD [SGI_ACL_FILE] XFS_DA_OP_RENAME=>xfs_attr3_leaf_remove() Aug 1 10:44:23.794670 vsa-0000000a-vc-0 kernel: [177522.836718] [14069][at]xfs [xfs_attr3_leaf_remove:1889] XFS(dm-79): ino[147144507861] bp[0x1121416a48] leaf.count=2 REMOVE idx=1 Aug 1 10:44:23.794671 vsa-0000000a-vc-0 kernel: [177522.836722] [14069][at]xfs [xfs_attr3_leaf_remove:2020] XFS(dm-79): ino[147144507861] bp[0x1121416a48] leaf.count=1 REMOVE DONE idx=1 Aug 1 10:44:23.800954 vsa-0000000a-vc-0 kernel: [177522.840338] [13689][at]xfs*[xfs_attr3_leaf_verify:202] XFS(dm-79): ichdr.count==0 bp[0x1156aacf60] Aug 1 10:44:23.800971 vsa-0000000a-vc-0 kernel: [177522.840370] XFS (dm-79): Metadata corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 [xfs], block 0x1156aacf60 Aug 1 10:44:23.800972 vsa-0000000a-vc-0 kernel: [177522.841673] XFS (dm-79): Unmount and run xfs_repair Aug 1 10:44:23.800973 vsa-0000000a-vc-0 kernel: [177522.842415] XFS (dm-79): First 64 bytes of corrupted metadata buffer: Aug 1 10:44:23.802201 vsa-0000000a-vc-0 kernel: [177522.843467] ffff88083286a000: 00 00 00 00 00 00 00 00 fb ee 00 00 00 00 00 00 ................ Aug 1 10:44:23.804028 vsa-0000000a-vc-0 kernel: [177522.844637] ffff88083286a010: 10 00 00 00 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... Aug 1 10:44:23.804032 vsa-0000000a-vc-0 kernel: [177522.845487] ffff88083286a020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Aug 1 10:44:23.804034 vsa-0000000a-vc-0 kernel: [177522.846419] ffff88083286a030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Aug 1 10:44:23.805714 vsa-0000000a-vc-0 kernel: [177522.847330] XFS (dm-79): xfs_do_force_shutdown(0x8) called from line 1244 of file /mnt/homes/alex/zadara-kernel-3.18-fixes//fs/xfs/xfs_buf.c. Return address = 0xffffffffc1024a40 Aug 1 10:44:23.805721 vsa-0000000a-vc-0 kernel: [177522.847334] ------------[ cut here ]------------ Aug 1 10:44:23.805723 vsa-0000000a-vc-0 kernel: [177522.847374] WARNING: CPU: 3 PID: 13689 at /mnt/homes/alex/zadara-kernel-3.18-fixes//fs/xfs/zxfs.c:40 zxfs_error+0x6a/0x290 [xfs]() Aug 1 10:44:23.805724 vsa-0000000a-vc-0 kernel: [177522.847376] XFS(dm-79): SHUTDOWN!!! old_flags=0x0 new_flags=0x8 Aug 1 10:44:23.805726 vsa-0000000a-vc-0 kernel: [177522.847377] Modules linked in: xt_nat(E) veth(E) xt_addrtype(E) br_netfilter(E) xfrm_user(E) xfrm4_tunnel(E) tunnel4(E) ipcomp(E) xfrm_ipcomp(E) esp4(E) ah4(E) 8021q(E) garp(E) mrp(E) xt_multiport(E) xfs(OE) sd_mod(E) ib_iser(OE) iscsi_tcp(OE) libiscsi_tcp(OE) libiscsi(OE) scsi_transport_iscsi(OE) bonding(E) dm_zcache(OE) btrfs(OE) raid456(OE) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) xor(E) async_tx(E) raid6_pq(E) raid1(OE) md_mod(OE) rdma_ucm(OE) ib_uverbs(OE) mlx4_ib(OE) mlx4_en(OE) ipt_MASQUERADE(E) nf_nat_masquerade_ipv4(E) iptable_nat(E) nf_nat_ipv4(E) nf_nat(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) xt_conntrack(E) nf_conntrack(E) ipt_REJECT(E) nf_reject_ipv4(E) xt_CHECKSUM(E) iptable_mangle(E) xt_tcpudp(E) bridge(E) stp(E) llc(E) vxlan(E) ip6_udp_tunnel(E) udp_tunnel(E) ptp(E) pps_core(E) ip6table_filter(E) ip6_tables(E) iptable_filter(E) ip_tables(E) x_tables(E) mlx4_core(OE) deflate(E) ctr(E) twofish_generic(E) twofish_avx_x86_64(E) twofish_x86_64_3way(E) twofish_x86_64(E) twofish_common(E) camellia_generic(E) camellia_aesni_avx2(E) camellia_aesni_avx_x86_64(E) camellia_x86_64(E) serpent_avx2(E) serpent_avx_x86_64(E) serpent_sse2_x86_64(E) xts(E) serpent_generic(E) blowfish_generic(E) blowfish_x86_64(E) blowfish_common(E) cast5_avx_x86_64(E) cast5_generic(E) cast_common(E) des3_ede_x86_64(E) des_generic(E) cmac(E) xcbc(E) rmd160(E) crypto_null(E) af_key(E) xfrm_algo(E) isert_scst(OE) rdma_cm(OE) iw_cm(OE) ib_cm(OE) ib_sa(OE) ib_mad(OE) ib_core(OE) ib_addr(OE) compat(OE) iscsi_scst(OE) scst_utgt(OE) scst_vdisk(OE) libcrc32c(E) scst(OE) kvm_intel(E) kvm(E) crct10dif_pclmul(E) crc32_pclmul(E) ghash_clmulni_intel(E) aesni_intel(E) aes_x86_64(E) lrw(E) gf128mul(E) dm_multipath(OE) glue_helper(E) ablk_helper(E) cryptd(E) scsi_dh(E) mac_hid(E) serio_raw(E) nls_iso8859_1(E) nfsd(OE) auth_rpcgss(E) nfs_acl(E) nfs(E) lockd(E) grace(E) sunrpc(E) fscache(E) ttm(E) drm_kms_helper(E) drm(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) i2c_piix4(E) i6300esb(E) lp(E) parport(E) dm_iostat(OE) zadara_utils(OE) ata_generic(E) pata_acpi(E) ata_piix(E) libata(E) scsi_mod(OE) psmouse(E) [last unloaded: xfs] Aug 1 10:44:23.805728 vsa-0000000a-vc-0 kernel: [177522.847491] CPU: 3 PID: 13689 Comm: xfsaild/dm-79 Tainted: G OE 3.18.19-zadara05 #1 Aug 1 10:44:23.805736 vsa-0000000a-vc-0 kernel: [177522.847493] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 Aug 1 10:44:23.805738 vsa-0000000a-vc-0 kernel: [177522.847495] 0000000000000009 ffff8806fbb5bb38 ffffffff81710c85 0000000000000000 Aug 1 10:44:23.805739 vsa-0000000a-vc-0 kernel: [177522.847498] ffff8806fbb5bb88 ffff8806fbb5bb78 ffffffff81072df1 2e2e202030302030 Aug 1 10:44:23.805740 vsa-0000000a-vc-0 kernel: [177522.847501] 0000000000000000 0000000000000008 ffff880747bbd000 0000000000000000 Aug 1 10:44:23.805740 vsa-0000000a-vc-0 kernel: [177522.847504] Call Trace: Aug 1 10:44:23.805741 vsa-0000000a-vc-0 kernel: [177522.847512] [<ffffffff81710c85>] dump_stack+0x4e/0x71 Aug 1 10:44:23.805741 vsa-0000000a-vc-0 kernel: [177522.847517] [<ffffffff81072df1>] warn_slowpath_common+0x81/0xa0 Aug 1 10:44:23.805742 vsa-0000000a-vc-0 kernel: [177522.847520] [<ffffffff81072e56>] warn_slowpath_fmt+0x46/0x50 Aug 1 10:44:23.805743 vsa-0000000a-vc-0 kernel: [177522.847538] [<ffffffffc103f423>] ? xfs_notice+0x53/0x60 [xfs] Aug 1 10:44:23.805744 vsa-0000000a-vc-0 kernel: [177522.847566] [<ffffffffc107683a>] zxfs_error+0x6a/0x290 [xfs] Aug 1 10:44:23.805744 vsa-0000000a-vc-0 kernel: [177522.847581] [<ffffffffc1031033>] xfs_do_force_shutdown+0x33/0x170 [xfs] Aug 1 10:44:23.805745 vsa-0000000a-vc-0 kernel: [177522.847594] [<ffffffffc1024a40>] ? _xfs_buf_ioapply+0xa0/0x430 [xfs] Aug 1 10:44:23.805745 vsa-0000000a-vc-0 kernel: [177522.847607] [<ffffffffc10269ab>] ? __xfs_buf_delwri_submit+0x22b/0x290 [xfs] Aug 1 10:44:23.805746 vsa-0000000a-vc-0 kernel: [177522.847619] [<ffffffffc1024a40>] _xfs_buf_ioapply+0xa0/0x430 [xfs] Aug 1 10:44:23.805747 vsa-0000000a-vc-0 kernel: [177522.847623] [<ffffffff8109e260>] ? wake_up_state+0x20/0x20 Aug 1 10:44:23.805754 vsa-0000000a-vc-0 kernel: [177522.847634] [<ffffffffc10269ab>] ? __xfs_buf_delwri_submit+0x22b/0x290 [xfs] Aug 1 10:44:23.805755 vsa-0000000a-vc-0 kernel: [177522.847645] [<ffffffffc10265d8>] xfs_buf_submit+0x68/0x210 [xfs] Aug 1 10:44:23.805756 vsa-0000000a-vc-0 kernel: [177522.847656] [<ffffffffc10269ab>] __xfs_buf_delwri_submit+0x22b/0x290 [xfs] Aug 1 10:44:23.805756 vsa-0000000a-vc-0 kernel: [177522.847667] [<ffffffffc10277c0>] ? xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] Aug 1 10:44:23.805757 vsa-0000000a-vc-0 kernel: [177522.847683] [<ffffffffc1057090>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs] Aug 1 10:44:23.805758 vsa-0000000a-vc-0 kernel: [177522.847695] [<ffffffffc10277c0>] xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] Aug 1 10:44:23.805759 vsa-0000000a-vc-0 kernel: [177522.847710] [<ffffffffc10572bb>] xfsaild+0x22b/0x630 [xfs] Aug 1 10:44:23.805759 vsa-0000000a-vc-0 kernel: [177522.847724] [<ffffffffc1057090>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs] Aug 1 10:44:23.805760 vsa-0000000a-vc-0 kernel: [177522.847728] [<ffffffff810911b9>] kthread+0xc9/0xe0 Aug 1 10:44:23.805760 vsa-0000000a-vc-0 kernel: [177522.847731] [<ffffffff810910f0>] ? kthread_create_on_node+0x180/0x180 Aug 1 10:44:23.805761 vsa-0000000a-vc-0 kernel: [177522.847736] [<ffffffff81717918>] ret_from_fork+0x58/0x90 Aug 1 10:44:23.805762 vsa-0000000a-vc-0 kernel: [177522.847745] [<ffffffff810910f0>] ? kthread_create_on_node+0x180/0x180 -----Original Message----- From: Shyam Kaushik Sent: Wednesday, July 26, 2017 3:18 PM To: Alex Lyakas ; yair@zadarastorage.com Subject: FW: Metadata corruption at xfs_attr3_leaf_write_verify() -----Original Message----- From: Brian Foster [mailto:bfoster@redhat.com] Sent: 26 July 2017 17:46 To: Shyam Kaushik Cc: dchinner@redhat.com; Dave Chinner; linux-xfs@vger.kernel.org Subject: Re: Metadata corruption at xfs_attr3_leaf_write_verify() On Wed, Jul 26, 2017 at 10:52:50AM +0530, Shyam Kaushik wrote: > Hi Dave, > > From time to time we hit an xfs corruption when xattr leaf is attempted to > be written when it has ichdr.count==0. > > We are on an old kernel 3.18.19. We managed to capture xfs trace buffer > closer to the problem time. > > This is the corruption report > Jul 20 05:22:27.189727 node1 kernel: [466290.765299] XFS (dm-78): Metadata > corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 [xfs], block > 0x9698734d8 > Jul 20 05:22:27.189741 node1 kernel: [466290.767279] XFS (dm-78): Unmount > and run xfs_repair > Jul 20 05:22:27.189743 node1 kernel: [466290.768022] XFS (dm-78): First 64 > bytes of corrupted metadata buffer: > Jul 20 05:22:27.191635 node1 kernel: [466290.768832] ffff88002b4bf000: 00 > 00 00 00 00 00 00 00 fb ee 00 00 00 00 00 00 ................ > Jul 20 05:22:27.192949 node1 kernel: [466290.770163] ffff88002b4bf010: 10 > 00 00 00 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... > Jul 20 05:22:27.192953 node1 kernel: [466290.771264] ffff88002b4bf020: 00 > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ > Jul 20 05:22:27.195921 node1 kernel: [466290.772815] ffff88002b4bf030: 00 > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ > > From xfs xattr debug trace, it appears that a file is created within a > directory having default ACL set. This causes file creation to insert xattr > leaf during file creation. This completes queuing an AIL. Immediately after > this an explicit xfs_setattr is being done on the same file which alters the > default ACL & this causes default ACL to be removed/added. It looks like > this 2nd set attr is somehow influencing the first AIL entry that it is > being seen with ichr.count==0 during the write. > I didn't notice anything on a quick pass through the code that would lead to this situation. It looks to me that the initial attr creates the leaf (where count is initialized to 0), but then adds the xattr in the same transaction (which should bump ichdr.count). The next set of SGI_ACL_FILE calls xfs_attr_leaf_add[_work]() before it rolls the transaction, which looks like it should bump ichdr.count again before we flip the inactive flags and remove the old attr. The output above clearly shows ichdr.count == 0, so I could easily be missing something or something else could be going on here. Unless somebody else chimes in with something more concrete, could you add a trace_printk() statement to xfs_attr3_leaf_verify() at the appropriate point where the verifier fails and re-collect the above tracepoint data? You could print out bp->b_bno just so we can correspond the log message to the tracepoint, but otherwise I'm just more curious to see where in the sequence of the xattr replace that the verifier happens to trigger and fail. Note that when you enable the attr tracepoints, you may have to include '-e print' to make sure the trace_printk() is enabled as well. E.g., something like 'trace-cmd start -e xfs:xfs_attr_* -e print' should work. Brian > I can pass the full xfs debug trace if required. Here is the snippet of > debug trace causing the issue > > <...>-18953 [004] ...1 466290.749358: xfs_attr_sf_create: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749359: xfs_attr_sf_addname: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749361: xfs_attr_sf_lookup: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749362: xfs_attr_sf_to_leaf: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749430: xfs_attr_leaf_create: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749454: xfs_attr_leaf_addname: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749456: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749457: xfs_attr_leaf_add: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749458: xfs_attr_leaf_add_work: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.749649: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.749908: xfs_attr_leaf_get: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval > 0xea9061c8 op_flags > <...>-18953 [004] ...1 466290.749910: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval > 0xea9061c8 op_flags > <...>-18953 [004] ...1 466290.749918: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.749931: xfs_attr_leaf_get: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval > 0x487716dd op_flags > <...>-18953 [004] ...1 466290.749932: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval > 0x487716dd op_flags > <...>-18953 [004] ...1 466290.749984: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.749990: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750063: xfs_setattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750257: xfs_attr_leaf_addname: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750260: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750261: xfs_attr_leaf_replace: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750262: xfs_attr_leaf_add: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750262: xfs_attr_leaf_add_work: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750270: xfs_attr_leaf_flipflags: > dev 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 > hashval 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750275: xfs_attr_leaf_remove: dev > 253:78 ino 0x1749833903 name SGI_ACL_FILE namelen 12 valuelen 100 hashval > 0x275b19c4 op_flags RENAME|ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750461: xfs_attr_leaf_removename: > dev 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 0 hashval > 0xea9061c8 op_flags OKNOENT > <...>-18953 [004] ...1 466290.750463: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 0 hashval 0xea9061c8 > op_flags OKNOENT > <...>-18953 [004] ...1 466290.750474: xfs_attr_leaf_addname: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval > 0x487716dd op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750475: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval > 0x487716dd op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750476: xfs_attr_leaf_add: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval > 0x487716dd op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750476: xfs_attr_leaf_add_work: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 49 hashval > 0x487716dd op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750645: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750648: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750645: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750648: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750659: xfs_attr_leaf_get: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval > 0x487716dd op_flags > <...>-18953 [004] ...1 466290.750661: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name SAMBA_PAI namelen 9 valuelen 1024 hashval > 0x487716dd op_flags > <...>-18953 [004] ...1 466290.750744: xfs_getattr: dev 253:78 ino > 0x1749833903 > <...>-18953 [004] ...1 466290.750791: xfs_attr_leaf_addname: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 > op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750793: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 > op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750794: xfs_attr_leaf_add: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 > op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.750794: xfs_attr_leaf_add_work: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 444 hashval 0xea9061c8 > op_flags ADDNAME|OKNOENT > <...>-18953 [004] ...1 466290.751029: xfs_attr_leaf_get: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval > 0xea9061c8 op_flags > <...>-18953 [004] ...1 466290.751031: xfs_attr_leaf_lookup: dev > 253:78 ino 0x1749833903 name NTACL namelen 5 valuelen 1024 hashval > 0xea9061c8 op_flags > > > Any pointers/input to check this further is greatly appreciated! Thanks. > > --Shyam > > On Tue, Apr 26, 2016 at 4:10 PM, Shyam Kaushik <shyam@zadarastorage.com> > wrote: > Hi Eric, > > Yes this is a non-CRC FS. The workload is we a custom application that > does several (16 threads) file create/read/writes/update xattrs on a XFS > mounted over raw disk. > > There is no messages prior to this & we hit this once in a few days (like > every 4-5 days). I will try your suggestion of running with xfs_attr_* > tracepoints all the time so that when we hit this error we have better > info. Please let me know if you prefer to add further debug prints. > Thanks. > > --Shyam > > > Eric Sandeen sandeen at sandeen.net wrote: > > On Mon Apr 25 16:57:11 CDT 2016 > > > > Is this a non-crc filesystem? > > > > > > XFS_ATTR_LEAF_MAGIC is ok (if it's a non-crc filesystem) > > > > Looks the same as the other report, tripping on: > > > > if (ichdr.count == 0) > > return false; > > > > A reproducer would be super here. At least maybe a description of the > > workload that hits it? > > > > Count is manipulated in things like attr leaf compaction... > > Any other messages prior to this? > > > > How often do you hit it? > > > > You could also turn on xfs_attr_* tracepoints, maybe. > > > > -Eric > > -----Original Message----- > From: Shyam Kaushik [mailto:shyam@zadarastorage.com] > Sent: 25 April 2016 22:22 > To: 'xfs@oss.sgi.com' > Cc: Alex Lyakas > Subject: Metadata corruption detected at > xfs_attr3_leaf_write_verify+0xe5/0x100 > > Hi Dave et al, > > We are periodically hitting the below metadata corruption with XFS over a > raw disk running several file copies with xattr operations on kernel > 3.18.19. Unmounting & running xfs_repair doesn't report any corruption. I > see that this was last reported here > http://oss.sgi.com/archives/xfs/2015-12/msg00224.html > > Unfortunately we dont have a reproducer, but this issue happens > periodically. We can add more debug prints & allow this issue to happen > again. Can you pls suggest any options to debug this further? Thanks > > Apr 20 21:58:03 node1 kernel: [16736.286370] XFS (dm-26): Metadata > corruption detected at xfs_attr3_leaf_write_verify+0xe5/0x100 [xfs], block > 0x19c5c728 > Apr 20 21:58:03 node1 kernel: [16736.289084] XFS (dm-26): Unmount and run > xfs_repair > Apr 20 21:58:03 node1 kernel: [16736.290257] XFS (dm-26): First 64 bytes > of corrupted metadata buffer: > Apr 20 21:58:03 node1 kernel: [16736.291797] ffff880123668000: 00 00 00 00 > 00 00 00 00 fb ee 00 00 00 00 00 00 ................ > Apr 20 21:58:03 node1 kernel: [16736.293823] ffff880123668010: 10 00 00 00 > 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... > Apr 20 21:58:03 node1 kernel: [16736.297504] ffff880123668020: 00 00 00 00 > 00 00 00 00 00 00 00 00 00 00 00 00 ................ > Apr 20 21:58:03 node1 kernel: [16736.299343] ffff880123668030: 00 00 00 00 > 00 00 00 00 00 00 00 00 00 00 00 00 ................ > Apr 20 21:58:03 node1 kernel: [16736.301465] XFS (dm-26): > xfs_do_force_shutdown(0x8) called from line 1244 of file fs/xfs/xfs_buf.c. > Return address = 0xffffffffc095cee0 > Apr 20 21:58:03 node1 kernel: [16736.301469] ------------[ cut here > ]------------ > Apr 20 21:58:03 node1 kernel: [16736.301551] XFS(dm-26): SHUTDOWN!!! > old_flags=0x0 new_flags=0x8 > Apr 20 21:58:03 node1 kernel: [16736.301703] CPU: 1 PID: 7857 Comm: > xfsaild/dm-26 Tainted: G OE 3.18.19 #1 > Apr 20 21:58:03 node1 kernel: [16736.301705] Hardware name: Bochs Bochs, > BIOS Bochs 01/01/2011 > Apr 20 21:58:03 node1 kernel: [16736.301707] 0000000000000009 > ffff88020c5ffb38 ffffffff81710c85 0000000000000000 > Apr 20 21:58:03 node1 kernel: [16736.301711] ffff88020c5ffb88 > ffff88020c5ffb78 ffffffff81072df1 2e2e202030302030 > Apr 20 21:58:03 node1 kernel: [16736.301715] 0000000000000000 > 0000000000000008 ffff88020c127000 0000000000000000 > Apr 20 21:58:03 node1 kernel: [16736.301718] Call Trace: > Apr 20 21:58:03 node1 kernel: [16736.301769] [<ffffffff81710c85>] > dump_stack+0x4e/0x71 > Apr 20 21:58:03 node1 kernel: [16736.301780] [<ffffffff81072df1>] > warn_slowpath_common+0x81/0xa0 > Apr 20 21:58:03 node1 kernel: [16736.301784] [<ffffffff81072e56>] > warn_slowpath_fmt+0x46/0x50 > Apr 20 21:58:03 node1 kernel: [16736.301860] [<ffffffffc09693f3>] > xfs_do_force_shutdown+0x33/0x170 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.301921] [<ffffffffc095cee0>] ? > _xfs_buf_ioapply+0xa0/0x430 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.301951] [<ffffffffc095ee4b>] ? > __xfs_buf_delwri_submit+0x22b/0x290 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302066] [<ffffffffc095cee0>] > _xfs_buf_ioapply+0xa0/0x430 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302137] [<ffffffff8109e260>] ? > wake_up_state+0x20/0x20 > Apr 20 21:58:03 node1 kernel: [16736.302162] [<ffffffffc095ee4b>] ? > __xfs_buf_delwri_submit+0x22b/0x290 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302183] [<ffffffffc095ea78>] > xfs_buf_submit+0x68/0x210 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302241] [<ffffffffc095ee4b>] > __xfs_buf_delwri_submit+0x22b/0x290 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302267] [<ffffffffc095fc60>] ? > xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302291] [<ffffffffc098f440>] ? > xfs_trans_ail_cursor_first+0x90/0x90 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302308] [<ffffffffc095fc60>] > xfs_buf_delwri_submit_nowait+0x20/0x30 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302333] [<ffffffffc098f66b>] > xfsaild+0x22b/0x630 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302513] [<ffffffffc098f440>] ? > xfs_trans_ail_cursor_first+0x90/0x90 [xfs] > Apr 20 21:58:03 node1 kernel: [16736.302518] [<ffffffff810911b9>] > kthread+0xc9/0xe0 > Apr 20 21:58:03 node1 kernel: [16736.302522] [<ffffffff810910f0>] ? > kthread_create_on_node+0x180/0x180 > Apr 20 21:58:03 node1 kernel: [16736.302530] [<ffffffff81717918>] > ret_from_fork+0x58/0x90 > Apr 20 21:58:03 node1 kernel: [16736.302549] [<ffffffff810910f0>] ? > kthread_create_on_node+0x180/0x180 > Apr 20 21:58:03 node1 kernel: [16736.302551] ---[ end trace > 0bb81b88fdd6a298 ]--- > > --Shyam > -- > To unsubscribe from this list: send the line "unsubscribe linux-xfs" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-08-01 17:30 ` Alex Lyakas @ 2017-08-01 18:22 ` Eric Sandeen 2017-08-01 18:57 ` Alex Lyakas 2017-08-01 23:18 ` Dave Chinner 1 sibling, 1 reply; 13+ messages in thread From: Eric Sandeen @ 2017-08-01 18:22 UTC (permalink / raw) To: Alex Lyakas, linux-xfs; +Cc: Shyam Kaushik, bfoster, dchinner, david On 8/1/17 12:30 PM, Alex Lyakas wrote: > Greetings XFS developers, David, Brian, > > We did additional debugging on this issue. The problematic flow happens to be the following: > > - New inode (regular file) is being created. > - As part of creation, due to parent directory having a default ACL, initial ACL is applied to the inode. > - This ACL is applied as an extended attribute with name "SGI_ACL_FILE" and value length of 100 bytes. > - XFS tries to add this attribute into the inline inode attribute fork area (AKA shortform). > - But 100 bytes is too large for the shortform, so XFS creates an empty shortform and then calls xfs_attr_shortform_to_leaf() > - This calls xfs_attr3_leaf_create() and creates a leaf with zero attributes. > - Before XFS is able to add the attribute to the leaf, the xfsaild thread wants to write this leaf to disk, and trips over the assert in xfs_attr3_leaf_verify, that ichdr.count should not be 0 > > So this seems like a race condition, where xfsaild writes a not-fully-prepared xfs_buf to disk. To my understanding this can lead to different kinds of corruptions. Interesting, this seems possibly related to this commit, which addresses a similar issue only during log replay: commit 2e1d23370e75d7d89350d41b4ab58c7f6a0e26b2 Author: Eric Sandeen <sandeen@redhat.com> Date: Fri Dec 9 16:49:47 2016 +1100 xfs: ignore leaf attr ichdr.count in verifier during log replay When we create a new attribute, we first create a shortform attribute, and try to fit the new attribute into it. If that fails, we copy the (empty) attribute into a leaf attribute, and do the copy again. Thus there can be a transient state where we have an empty leaf attribute. If we encounter this during log replay, the verifier will fail. So add a test to ignore this part of the leaf attr verification during log replay. Thanks as usual to dchinner for spotting the problem. Signed-off-by: Eric Sandeen <sandeen@redhat.com> Reviewed-by: Christoph Hellwig <hch@lst.de> Signed-off-by: Dave Chinner <david@fromorbit.com> -Eric ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-08-01 18:22 ` Eric Sandeen @ 2017-08-01 18:57 ` Alex Lyakas 2017-08-01 19:02 ` Eric Sandeen 0 siblings, 1 reply; 13+ messages in thread From: Alex Lyakas @ 2017-08-01 18:57 UTC (permalink / raw) To: linux-xfs, Eric Sandeen; +Cc: Shyam Kaushik, bfoster, dchinner, david Hi Eric, Thanks for your response. I confirm that during log replay we also see this issue from time to time. However, our main problem is that during normal operation we trip on this assert, and this causes XFS to shutdown, causing outage. Please see the stack trace that I posted in the previous email; it does not happen during log replay. But [2] shows an example of this happening during log replay. Thanks, Alex. [2] Aug 1 10:45:10.787639 vsa-0000000a-vc-0 kernel: [177569.829977] XFS (dm-79): Mounting V4 Filesystem Aug 1 10:45:11.268635 vsa-0000000a-vc-0 kernel: [177570.310819] XFS (dm-79): Starting recovery (logdev: internal) Aug 1 10:45:15.529417 vsa-0000000a-vc-0 kernel: [177574.570695] [10050][at]xfs*[xfs_attr3_leaf_verify:202] XFS(dm-79): ichdr.count==0 bp[0xcc4cfff50] Aug 1 10:45:15.529424 vsa-0000000a-vc-0 kernel: [177574.570723] XFS (dm-79): Metadata corruption detected at xfs_attr3_leaf_read_verify+0x4f/0xf0 [xfs], block 0xcc4cfff50 Aug 1 10:45:15.529426 vsa-0000000a-vc-0 kernel: [177574.571788] XFS (dm-79): Unmount and run xfs_repair Aug 1 10:45:15.531314 vsa-0000000a-vc-0 kernel: [177574.572271] XFS (dm-79): First 64 bytes of corrupted metadata buffer: Aug 1 10:45:15.531316 vsa-0000000a-vc-0 kernel: [177574.572887] ffff88014f0a8000: 00 00 00 00 00 00 00 00 fb ee 00 00 00 00 00 00 ................ Aug 1 10:45:15.531317 vsa-0000000a-vc-0 kernel: [177574.573698] ffff88014f0a8010: 10 00 00 00 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... Aug 1 10:45:15.532953 vsa-0000000a-vc-0 kernel: [177574.574514] ffff88014f0a8020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Aug 1 10:45:15.532956 vsa-0000000a-vc-0 kernel: [177574.575332] ffff88014f0a8030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Aug 1 10:45:15.534630 vsa-0000000a-vc-0 kernel: [177574.576161] XFS (dm-79): metadata I/O error: block 0xcc4cfff50 ("xfs_trans_read_buf_map") error 117 numblks 8 Aug 1 10:45:15.556831 vsa-0000000a-vc-0 kernel: [177574.598119] [10050][at]xfs*[xfs_attr3_leaf_verify:202] XFS(dm-79): ichdr.count==0 bp[0xd7c4c4ab0] Aug 1 10:45:15.556837 vsa-0000000a-vc-0 kernel: [177574.598134] XFS (dm-79): Metadata corruption detected at xfs_attr3_leaf_read_verify+0x4f/0xf0 [xfs], block 0xd7c4c4ab0 Aug 1 10:45:15.556838 vsa-0000000a-vc-0 kernel: [177574.599210] XFS (dm-79): Unmount and run xfs_repair Aug 1 10:45:15.557937 vsa-0000000a-vc-0 kernel: [177574.599686] XFS (dm-79): First 64 bytes of corrupted metadata buffer: Aug 1 10:45:15.557939 vsa-0000000a-vc-0 kernel: [177574.600319] ffff880150b63000: 00 00 00 00 00 00 00 00 fb ee 00 00 00 00 00 00 ................ Aug 1 10:45:15.559643 vsa-0000000a-vc-0 kernel: [177574.601180] ffff880150b63010: 10 00 00 00 00 20 0f e0 00 00 00 00 00 00 00 00 ..... .......... Aug 1 10:45:15.559646 vsa-0000000a-vc-0 kernel: [177574.602023] ffff880150b63020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Aug 1 10:45:15.561367 vsa-0000000a-vc-0 kernel: [177574.602887] ffff880150b63030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ Aug 1 10:45:15.562632 vsa-0000000a-vc-0 kernel: [177574.603787] XFS (dm-79): metadata I/O error: block 0xd7c4c4ab0 ("xfs_trans_read_buf_map") error 117 numblks 8 Aug 1 10:45:15.562636 vsa-0000000a-vc-0 kernel: [177574.604767] XFS (dm-79): Ending recovery (logdev: internal) -----Original Message----- From: Eric Sandeen Sent: Tuesday, August 01, 2017 9:22 PM To: Alex Lyakas ; linux-xfs@vger.kernel.org Cc: Shyam Kaushik ; bfoster@redhat.com ; dchinner@redhat.com ; david@fromorbit.com Subject: Re: Metadata corruption at xfs_attr3_leaf_write_verify() On 8/1/17 12:30 PM, Alex Lyakas wrote: > Greetings XFS developers, David, Brian, > > We did additional debugging on this issue. The problematic flow happens to > be the following: > > - New inode (regular file) is being created. > - As part of creation, due to parent directory having a default ACL, > initial ACL is applied to the inode. > - This ACL is applied as an extended attribute with name "SGI_ACL_FILE" > and value length of 100 bytes. > - XFS tries to add this attribute into the inline inode attribute fork > area (AKA shortform). > - But 100 bytes is too large for the shortform, so XFS creates an empty > shortform and then calls xfs_attr_shortform_to_leaf() > - This calls xfs_attr3_leaf_create() and creates a leaf with zero > attributes. > - Before XFS is able to add the attribute to the leaf, the xfsaild thread > wants to write this leaf to disk, and trips over the assert in > xfs_attr3_leaf_verify, that ichdr.count should not be 0 > > So this seems like a race condition, where xfsaild writes a > not-fully-prepared xfs_buf to disk. To my understanding this can lead to > different kinds of corruptions. Interesting, this seems possibly related to this commit, which addresses a similar issue only during log replay: commit 2e1d23370e75d7d89350d41b4ab58c7f6a0e26b2 Author: Eric Sandeen <sandeen@redhat.com> Date: Fri Dec 9 16:49:47 2016 +1100 xfs: ignore leaf attr ichdr.count in verifier during log replay When we create a new attribute, we first create a shortform attribute, and try to fit the new attribute into it. If that fails, we copy the (empty) attribute into a leaf attribute, and do the copy again. Thus there can be a transient state where we have an empty leaf attribute. If we encounter this during log replay, the verifier will fail. So add a test to ignore this part of the leaf attr verification during log replay. Thanks as usual to dchinner for spotting the problem. Signed-off-by: Eric Sandeen <sandeen@redhat.com> Reviewed-by: Christoph Hellwig <hch@lst.de> Signed-off-by: Dave Chinner <david@fromorbit.com> -Eric ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-08-01 18:57 ` Alex Lyakas @ 2017-08-01 19:02 ` Eric Sandeen 0 siblings, 0 replies; 13+ messages in thread From: Eric Sandeen @ 2017-08-01 19:02 UTC (permalink / raw) To: Alex Lyakas, linux-xfs; +Cc: Shyam Kaushik, bfoster, dchinner, david On 8/1/17 1:57 PM, Alex Lyakas wrote: > Hi Eric, > > Thanks for your response. > > I confirm that during log replay we also see this issue from time to > time. However, our main problem is that during normal operation we > trip on this assert, and this causes XFS to shutdown, causing outage. > Please see the stack trace that I posted in the previous email; it > does not happen during log replay. Yep I understand that, I'm just noting that this transitional state has (recently?) caused trouble in other areas as well. -Eric ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-08-01 17:30 ` Alex Lyakas 2017-08-01 18:22 ` Eric Sandeen @ 2017-08-01 23:18 ` Dave Chinner 2017-08-02 8:38 ` Alex Lyakas 1 sibling, 1 reply; 13+ messages in thread From: Dave Chinner @ 2017-08-01 23:18 UTC (permalink / raw) To: Alex Lyakas; +Cc: linux-xfs, Shyam Kaushik, bfoster, dchinner On Tue, Aug 01, 2017 at 08:30:31PM +0300, Alex Lyakas wrote: > Greetings XFS developers, David, Brian, > > We did additional debugging on this issue. The problematic flow > happens to be the following: > > - New inode (regular file) is being created. > - As part of creation, due to parent directory having a default ACL, > initial ACL is applied to the inode. > - This ACL is applied as an extended attribute with name > "SGI_ACL_FILE" and value length of 100 bytes. > - XFS tries to add this attribute into the inline inode attribute > fork area (AKA shortform). > - But 100 bytes is too large for the shortform, so XFS creates an > empty shortform and then calls xfs_attr_shortform_to_leaf() > - This calls xfs_attr3_leaf_create() and creates a leaf with zero > attributes. > - Before XFS is able to add the attribute to the leaf, the xfsaild > thread wants to write this leaf to disk, and trips over the assert > in xfs_attr3_leaf_verify, that ichdr.count should not be 0 Ok, this makes it pretty obvious as to what's going on here. The new attribute leaf buffer is not held locked across the transaction roll between the shortform->leaf modification and the addition of the new entry. As a result the attribute buffer modification being made is not atomic from an operational perspective. Hence the AIL push can grab it in the transient state of "just created" after the initial transaction is rolled because the buffer has been released. Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-08-01 23:18 ` Dave Chinner @ 2017-08-02 8:38 ` Alex Lyakas 2017-08-02 11:50 ` Dave Chinner 2017-08-07 13:55 ` Libor Klepáč 0 siblings, 2 replies; 13+ messages in thread From: Alex Lyakas @ 2017-08-02 8:38 UTC (permalink / raw) To: Dave Chinner; +Cc: linux-xfs, Shyam Kaushik, bfoster, dchinner Hello Dave, Thank you for your analysis. It sounds like this issue exists in recent kernels as well. We are reviewing some of the paths that operate xfs_buf's, but still we don't have enough understanding on how to properly lock out the xfs_buf from AIL grabbing it. Can you please point us at similar flows, where such locking is done? Or otherwise, should you propose a patch to fix this, we can test it. If possible, making the patch applicable to kernel 3.18.19 would be appreciated. I realize that this is an EOL kernel, but still it used to be a long-term kernel. Thanks, Alex. -----Original Message----- From: Dave Chinner Sent: Wednesday, August 02, 2017 2:18 AM To: Alex Lyakas Cc: linux-xfs@vger.kernel.org ; Shyam Kaushik ; bfoster@redhat.com ; dchinner@redhat.com Subject: Re: Metadata corruption at xfs_attr3_leaf_write_verify() On Tue, Aug 01, 2017 at 08:30:31PM +0300, Alex Lyakas wrote: > Greetings XFS developers, David, Brian, > > We did additional debugging on this issue. The problematic flow > happens to be the following: > > - New inode (regular file) is being created. > - As part of creation, due to parent directory having a default ACL, > initial ACL is applied to the inode. > - This ACL is applied as an extended attribute with name > "SGI_ACL_FILE" and value length of 100 bytes. > - XFS tries to add this attribute into the inline inode attribute > fork area (AKA shortform). > - But 100 bytes is too large for the shortform, so XFS creates an > empty shortform and then calls xfs_attr_shortform_to_leaf() > - This calls xfs_attr3_leaf_create() and creates a leaf with zero > attributes. > - Before XFS is able to add the attribute to the leaf, the xfsaild > thread wants to write this leaf to disk, and trips over the assert > in xfs_attr3_leaf_verify, that ichdr.count should not be 0 Ok, this makes it pretty obvious as to what's going on here. The new attribute leaf buffer is not held locked across the transaction roll between the shortform->leaf modification and the addition of the new entry. As a result the attribute buffer modification being made is not atomic from an operational perspective. Hence the AIL push can grab it in the transient state of "just created" after the initial transaction is rolled because the buffer has been released. Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-08-02 8:38 ` Alex Lyakas @ 2017-08-02 11:50 ` Dave Chinner 2017-08-07 14:31 ` Alex Lyakas 2017-08-07 13:55 ` Libor Klepáč 1 sibling, 1 reply; 13+ messages in thread From: Dave Chinner @ 2017-08-02 11:50 UTC (permalink / raw) To: Alex Lyakas; +Cc: linux-xfs, Shyam Kaushik, bfoster, dchinner On Wed, Aug 02, 2017 at 11:38:36AM +0300, Alex Lyakas wrote: > Hello Dave, > > Thank you for your analysis. It sounds like this issue exists in > recent kernels as well. It's effectively a zero day bug. The two-transaction conversion to leaf form is recognisable in this commit from Jun 1995: http://oss.sgi.com/cgi-bin/gitweb.cgi?p=archive/xfs-import.git;a=commitdiff;h=d4e0d38051ce61f9d8f330f59e0a99ed710d5f9e This was about a month after attr support first shows up in the XFS commit history, so it's been there forever.... > We are reviewing some of the paths that operate xfs_buf's, but still > we don't have enough understanding on how to properly lock out the > xfs_buf from AIL grabbing it. Can you please point us at similar > flows, where such locking is done? It's simple - if the buffer is locked, the AIL can't grab it. The buffer needs to be held locked across transaction commit and then rejoined to the new transaction after it is rolled. THis is acheived by using xfs_trans_bhold() in the initial transaction context, and after commit it is rejoined to the new transaction context. See the inode chunk allocation code in xfs_dir_ialloc() for an example of how this works. Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-08-02 11:50 ` Dave Chinner @ 2017-08-07 14:31 ` Alex Lyakas 0 siblings, 0 replies; 13+ messages in thread From: Alex Lyakas @ 2017-08-07 14:31 UTC (permalink / raw) To: Dave Chinner; +Cc: linux-xfs, Shyam Kaushik, bfoster, dchinner Hello Dave, Brian, I have posted an RFC patch, which seems to fix the issue in: https://www.spinics.net/lists/linux-xfs/msg08895.html Can you please review it? I am now working on posting a patch based on 4.13-rc4, which hopefully will make it easier to be accepted. Thanks, Alex. -----Original Message----- From: Dave Chinner Sent: Wednesday, August 02, 2017 2:50 PM To: Alex Lyakas Cc: linux-xfs@vger.kernel.org ; Shyam Kaushik ; bfoster@redhat.com ; dchinner@redhat.com Subject: Re: Metadata corruption at xfs_attr3_leaf_write_verify() On Wed, Aug 02, 2017 at 11:38:36AM +0300, Alex Lyakas wrote: > Hello Dave, > > Thank you for your analysis. It sounds like this issue exists in > recent kernels as well. It's effectively a zero day bug. The two-transaction conversion to leaf form is recognisable in this commit from Jun 1995: http://oss.sgi.com/cgi-bin/gitweb.cgi?p=archive/xfs-import.git;a=commitdiff;h=d4e0d38051ce61f9d8f330f59e0a99ed710d5f9e This was about a month after attr support first shows up in the XFS commit history, so it's been there forever.... > We are reviewing some of the paths that operate xfs_buf's, but still > we don't have enough understanding on how to properly lock out the > xfs_buf from AIL grabbing it. Can you please point us at similar > flows, where such locking is done? It's simple - if the buffer is locked, the AIL can't grab it. The buffer needs to be held locked across transaction commit and then rejoined to the new transaction after it is rolled. THis is acheived by using xfs_trans_bhold() in the initial transaction context, and after commit it is rejoined to the new transaction context. See the inode chunk allocation code in xfs_dir_ialloc() for an example of how this works. Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-08-02 8:38 ` Alex Lyakas 2017-08-02 11:50 ` Dave Chinner @ 2017-08-07 13:55 ` Libor Klepáč 2017-08-07 14:32 ` Alex Lyakas 1 sibling, 1 reply; 13+ messages in thread From: Libor Klepáč @ 2017-08-07 13:55 UTC (permalink / raw) To: Alex Lyakas; +Cc: Dave Chinner, linux-xfs, Shyam Kaushik, bfoster, dchinner Hello, can this be related to our problems on 4.9.x kernel, we have started to see after starting to use ACL? I have several crashes in this thread, it bites us usually once per month: https://www.spinics.net/lists/linux-xfs/msg07058.html Metadata buffer dump seems to be the same Thanks, Libor On středa 2. srpna 2017 11:38:36 CEST Alex Lyakas wrote: > Hello Dave, > > Thank you for your analysis. It sounds like this issue exists in recent > kernels as well. > > We are reviewing some of the paths that operate xfs_buf's, but still we > don't have enough understanding on how to properly lock out the xfs_buf from > AIL grabbing it. Can you please point us at similar flows, where such > locking is done? > > Or otherwise, should you propose a patch to fix this, we can test it. If > possible, making the patch applicable to kernel 3.18.19 would be > appreciated. I realize that this is an EOL kernel, but still it used to be a > long-term kernel. > > Thanks, > Alex. > > > > -----Original Message----- > From: Dave Chinner > Sent: Wednesday, August 02, 2017 2:18 AM > To: Alex Lyakas > Cc: linux-xfs@vger.kernel.org ; Shyam Kaushik ; bfoster@redhat.com ; > dchinner@redhat.com > Subject: Re: Metadata corruption at xfs_attr3_leaf_write_verify() > > On Tue, Aug 01, 2017 at 08:30:31PM +0300, Alex Lyakas wrote: > > Greetings XFS developers, David, Brian, > > > > We did additional debugging on this issue. The problematic flow > > happens to be the following: > > > > - New inode (regular file) is being created. > > - As part of creation, due to parent directory having a default ACL, > > initial ACL is applied to the inode. > > - This ACL is applied as an extended attribute with name > > "SGI_ACL_FILE" and value length of 100 bytes. > > - XFS tries to add this attribute into the inline inode attribute > > fork area (AKA shortform). > > - But 100 bytes is too large for the shortform, so XFS creates an > > empty shortform and then calls xfs_attr_shortform_to_leaf() > > - This calls xfs_attr3_leaf_create() and creates a leaf with zero > > attributes. > > - Before XFS is able to add the attribute to the leaf, the xfsaild > > thread wants to write this leaf to disk, and trips over the assert > > in xfs_attr3_leaf_verify, that ichdr.count should not be 0 > > Ok, this makes it pretty obvious as to what's going on here. The new > attribute leaf buffer is not held locked across the transaction roll > between the shortform->leaf modification and the addition of the new > entry. As a result the attribute buffer modification being made is > not atomic from an operational perspective. Hence the AIL push can > grab it in the transient state of "just created" after the initial > transaction is rolled because the buffer has been released. > > Cheers, > > Dave. > -------- [1] mailto:libor.klepac@bcom.cz [2] tel:+420377457676 [3] http://www.bcom.cz ^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: Metadata corruption at xfs_attr3_leaf_write_verify() 2017-08-07 13:55 ` Libor Klepáč @ 2017-08-07 14:32 ` Alex Lyakas 0 siblings, 0 replies; 13+ messages in thread From: Alex Lyakas @ 2017-08-07 14:32 UTC (permalink / raw) To: LiborKlepáč; +Cc: linux-xfs Hello Libor, Your crashes seem identical to what I am trying to fix. See https://www.spinics.net/lists/linux-xfs/msg08895.html. Thanks, Alex. -----Original Message----- From: LiborKlepáč Sent: Monday, August 07, 2017 4:55 PM To: Alex Lyakas Cc: Dave Chinner ; linux-xfs@vger.kernel.org ; Shyam Kaushik ; bfoster@redhat.com ; dchinner@redhat.com Subject: Re: Metadata corruption at xfs_attr3_leaf_write_verify() Hello, can this be related to our problems on 4.9.x kernel, we have started to see after starting to use ACL? I have several crashes in this thread, it bites us usually once per month: https://www.spinics.net/lists/linux-xfs/msg07058.html Metadata buffer dump seems to be the same Thanks, Libor On středa 2. srpna 2017 11:38:36 CEST Alex Lyakas wrote: > Hello Dave, > > Thank you for your analysis. It sounds like this issue exists in recent > kernels as well. > > We are reviewing some of the paths that operate xfs_buf's, but still we > don't have enough understanding on how to properly lock out the xfs_buf > from > AIL grabbing it. Can you please point us at similar flows, where such > locking is done? > > Or otherwise, should you propose a patch to fix this, we can test it. If > possible, making the patch applicable to kernel 3.18.19 would be > appreciated. I realize that this is an EOL kernel, but still it used to be > a > long-term kernel. > > Thanks, > Alex. > > > > -----Original Message----- > From: Dave Chinner > Sent: Wednesday, August 02, 2017 2:18 AM > To: Alex Lyakas > Cc: linux-xfs@vger.kernel.org ; Shyam Kaushik ; bfoster@redhat.com ; > dchinner@redhat.com > Subject: Re: Metadata corruption at xfs_attr3_leaf_write_verify() > > On Tue, Aug 01, 2017 at 08:30:31PM +0300, Alex Lyakas wrote: > > Greetings XFS developers, David, Brian, > > > > We did additional debugging on this issue. The problematic flow > > happens to be the following: > > > > - New inode (regular file) is being created. > > - As part of creation, due to parent directory having a default ACL, > > initial ACL is applied to the inode. > > - This ACL is applied as an extended attribute with name > > "SGI_ACL_FILE" and value length of 100 bytes. > > - XFS tries to add this attribute into the inline inode attribute > > fork area (AKA shortform). > > - But 100 bytes is too large for the shortform, so XFS creates an > > empty shortform and then calls xfs_attr_shortform_to_leaf() > > - This calls xfs_attr3_leaf_create() and creates a leaf with zero > > attributes. > > - Before XFS is able to add the attribute to the leaf, the xfsaild > > thread wants to write this leaf to disk, and trips over the assert > > in xfs_attr3_leaf_verify, that ichdr.count should not be 0 > > Ok, this makes it pretty obvious as to what's going on here. The new > attribute leaf buffer is not held locked across the transaction roll > between the shortform->leaf modification and the addition of the new > entry. As a result the attribute buffer modification being made is > not atomic from an operational perspective. Hence the AIL push can > grab it in the transient state of "just created" after the initial > transaction is rolled because the buffer has been released. > > Cheers, > > Dave. > -------- [1] mailto:libor.klepac@bcom.cz [2] tel:+420377457676 [3] http://www.bcom.cz ^ permalink raw reply [flat|nested] 13+ messages in thread
end of thread, other threads:[~2017-08-07 14:32 UTC | newest]
Thread overview: 13+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <CAPh1sj5oU6QRyH_cnzrkGJb6ed3XO4fGABJ4yJLPnb-ppqVJeg@mail.gmail.com>
2017-07-21 13:31 ` Metadata corruption detected at xfs_attr3_leaf_write_verify Shyam Kaushik
2017-07-26 5:22 ` Metadata corruption at xfs_attr3_leaf_write_verify() Shyam Kaushik
2017-07-26 12:15 ` Brian Foster
[not found] <d161b07cad6536b0baf285328cf99500@mail.gmail.com>
2017-08-01 17:30 ` Alex Lyakas
2017-08-01 18:22 ` Eric Sandeen
2017-08-01 18:57 ` Alex Lyakas
2017-08-01 19:02 ` Eric Sandeen
2017-08-01 23:18 ` Dave Chinner
2017-08-02 8:38 ` Alex Lyakas
2017-08-02 11:50 ` Dave Chinner
2017-08-07 14:31 ` Alex Lyakas
2017-08-07 13:55 ` Libor Klepáč
2017-08-07 14:32 ` Alex Lyakas
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox