xfs: fix double free of trans in log recovery on I/O error

XFS log recovery builds up an xlog_recover object as it passes through the log operations on the physical log. These structures are managed via a hash table and are allocated when a new transaction is encountered and freed once a commit operation for the transaction is encountered.

This state machine for active transactions is implemented by a combination of xlog_do_recovery_pass(), which walks through the log buffers and xlog_recover_process_data() which processes log operations within each buffer. The latter function decides whether to allocate a new xlog_recover, add to it or commit and ultimately free it. If an error occurs at any point during the lifecycle of a particular xlog_recover, xlog_recover_process_data() frees the object and returns an error.

xlog_recover_commit_trans() handles the final processing of the transaction. It submits whatever I/O is required for the transaction and frees xlog_recover object along with the transaction items it tracks. If an error occurs at the final stages of the commit operation, such as I/O failure, both xlog_recover_commit_trans() and xlog_recover_process_data() attempt to free the trans object.

Modify xlog_recover_commit_trans() to only free the trans object on successful completion of the trans, including any I/O errors that might occur when recovering the log.

Signed-off-by Brian Foster <[email protected]>

---

Hi all,

I found that the recent buffer I/O rework fixes didn't address the crash reproduced by the dm-flakey/log recovery test case I posted recently. I tracked the crash down to this, which allows the test to pass. This addresses the crash I saw when running the reproducer manually with the metadump that Alex posted as well.

FWIW, I also went back and tested the xfs_buf_iowait() experiment in both scenarios (Alex's metadump and xfstests test) and they all reproduce the same crash for me. I think that either I'm still not reproducing the original problem, something else might have contaminated the original xfs_buf_iowait() test to give a false positive, or something else entirely is going on.

Alex,

If you have a chance, I think it might be interesting to see whether you reproduce any problems with this patch. It looks like this is a regression introduced by:

2a84108f xfs: free the list of recovery items on error

... but I have no idea if that's in whatever kernel you're running.

Brian

 fs/xfs/xfs_log_recover.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

fs/xfs/xfs_log_recover.c +8 -4

index 176c4b3..daca9a6 100644
@@ -3528,10 +3528,15 @@ out:
        if (!list_empty(&done_list))
                list_splice_init(&done_list, &trans->r_itemq);
 
-       xlog_recover_free_trans(trans);
-
        error2 = xfs_buf_delwri_submit(&buffer_list);
-       return error ? error : error2;
+
+       if (!error)
+               error = error2;
+       /* caller frees trans on error */
+       if (!error)
+               xlog_recover_free_trans(trans);
+
+       return error;
 }
 
 STATIC int
--

1.8.3.1

Hi Brian,

Quoted 45 lines · Brian Foster

XFS log recovery builds up an xlog_recover object as it passes through the log operations on the physical log. These structures are managed via a hash table and are allocated when a new transaction is encountered and freed once a commit operation for the transaction is encountered.

This state machine for active transactions is implemented by a combination of xlog_do_recovery_pass(), which walks through the log buffers and xlog_recover_process_data() which processes log operations within each buffer. The latter function decides whether to allocate a new xlog_recover, add to it or commit and ultimately free it. If an error occurs at any point during the lifecycle of a particular xlog_recover, xlog_recover_process_data() frees the object and returns an error.

xlog_recover_commit_trans() handles the final processing of the transaction. It submits whatever I/O is required for the transaction and frees xlog_recover object along with the transaction items it tracks. If an error occurs at the final stages of the commit operation, such as I/O failure, both xlog_recover_commit_trans() and xlog_recover_process_data() attempt to free the trans object.

Modify xlog_recover_commit_trans() to only free the trans object on successful completion of the trans, including any I/O errors that might occur when recovering the log.

Signed-off-by Brian Foster <[email protected]>

---

Hi all,

I found that the recent buffer I/O rework fixes didn't address the crash reproduced by the dm-flakey/log recovery test case I posted recently. I tracked the crash down to this, which allows the test to pass. This addresses the crash I saw when running the reproducer manually with the metadump that Alex posted as well.

FWIW, I also went back and tested the xfs_buf_iowait() experiment in both scenarios (Alex's metadump and xfstests test) and they all reproduce the same crash for me. I think that either I'm still not reproducing the original problem, something else might have contaminated the original xfs_buf_iowait() test to give a false positive, or something else entirely is going on.

Alex,

Quoted 7 lines

If you have a chance, I think it might be interesting to see whether you reproduce any problems with this patch. It looks like this is a regression introduced by:

2a84108f xfs: free the list of recovery items on error

... but I have no idea if that's in whatever kernel you're running.

I am running kernel 3.8.13 with some changes (published at
https://github.com/zadarastorage/zadara-xfs-pushback), but this problem also happens on pristine 3.8.13 from
git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git,
branch linux-stable-3.8.y.

I do not have commit 2a84108f in this kernel. It was introduced in 3.14. I applied your patch to 3.8.13, but it doesn't fix the issue. Same problem happens when testing scenario that I described in
http://oss.sgi.com/pipermail/xfs/2014-August/037637.html.

Thanks,
Alex.

Quoted 28 lines

Brian

 fs/xfs/xfs_log_recover.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

fs/xfs/xfs_log_recover.c +8 -3

index 176c4b3..daca9a6 100644
@@ -3528,10 +3528,15 @@ out:
        if (!list_empty(&done_list))
                list_splice_init(&done_list, &trans->r_itemq);
 
-       xlog_recover_free_trans(trans);
-
        error2 = xfs_buf_delwri_submit(&buffer_list);
-       return error ? error : error2;
+
+       if (!error)
+               error = error2;
+       /* caller frees trans on error */
+       if (!error)
+               xlog_recover_free_trans(trans);
+
+       return error;
 }
 

Quoted 4 lines

fs/xfs/xfs_log_recover.c +0 -1

 STATIC int
--

1.8.3.1

Hi Brian,

Quoted 45 lines · Brian Foster

XFS log recovery builds up an xlog_recover object as it passes through the log operations on the physical log. These structures are managed via a hash table and are allocated when a new transaction is encountered and freed once a commit operation for the transaction is encountered.

This state machine for active transactions is implemented by a combination of xlog_do_recovery_pass(), which walks through the log buffers and xlog_recover_process_data() which processes log operations within each buffer. The latter function decides whether to allocate a new xlog_recover, add to it or commit and ultimately free it. If an error occurs at any point during the lifecycle of a particular xlog_recover, xlog_recover_process_data() frees the object and returns an error.

xlog_recover_commit_trans() handles the final processing of the transaction. It submits whatever I/O is required for the transaction and frees xlog_recover object along with the transaction items it tracks. If an error occurs at the final stages of the commit operation, such as I/O failure, both xlog_recover_commit_trans() and xlog_recover_process_data() attempt to free the trans object.

Modify xlog_recover_commit_trans() to only free the trans object on successful completion of the trans, including any I/O errors that might occur when recovering the log.

Signed-off-by Brian Foster <[email protected]>

---

Hi all,

I found that the recent buffer I/O rework fixes didn't address the crash reproduced by the dm-flakey/log recovery test case I posted recently. I tracked the crash down to this, which allows the test to pass. This addresses the crash I saw when running the reproducer manually with the metadump that Alex posted as well.

FWIW, I also went back and tested the xfs_buf_iowait() experiment in both scenarios (Alex's metadump and xfstests test) and they all reproduce the same crash for me. I think that either I'm still not reproducing the original problem, something else might have contaminated the original xfs_buf_iowait() test to give a false positive, or something else entirely is going on.

Alex,

Quoted 7 lines

If you have a chance, I think it might be interesting to see whether you reproduce any problems with this patch. It looks like this is a regression introduced by:

2a84108f xfs: free the list of recovery items on error

... but I have no idea if that's in whatever kernel you're running.

I am running kernel 3.8.13 with some changes (published at
https://github.com/zadarastorage/zadara-xfs-pushback), but this problem also happens on pristine 3.8.13 from
git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git,
branch linux-stable-3.8.y.

I do not have commit 2a84108f in this kernel. It was introduced in 3.14. I applied your patch to 3.8.13, but it doesn't fix the issue. Same problem happens when testing scenario that I described in
http://oss.sgi.com/pipermail/xfs/2014-August/037637.html.

Thanks,
Alex.

Quoted 28 lines

Brian

 fs/xfs/xfs_log_recover.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

fs/xfs/xfs_log_recover.c +8 -3

index 176c4b3..daca9a6 100644
@@ -3528,10 +3528,15 @@ out:
        if (!list_empty(&done_list))
                list_splice_init(&done_list, &trans->r_itemq);
 
-       xlog_recover_free_trans(trans);
-
        error2 = xfs_buf_delwri_submit(&buffer_list);
-       return error ? error : error2;
+
+       if (!error)
+               error = error2;
+       /* caller frees trans on error */
+       if (!error)
+               xlog_recover_free_trans(trans);
+
+       return error;
 }
 

Quoted 4 lines

fs/xfs/xfs_log_recover.c +0 -1

 STATIC int
--

1.8.3.1

Hi Brian,

Quoted 45 lines · Brian Foster

XFS log recovery builds up an xlog_recover object as it passes through the log operations on the physical log. These structures are managed via a hash table and are allocated when a new transaction is encountered and freed once a commit operation for the transaction is encountered.

This state machine for active transactions is implemented by a combination of xlog_do_recovery_pass(), which walks through the log buffers and xlog_recover_process_data() which processes log operations within each buffer. The latter function decides whether to allocate a new xlog_recover, add to it or commit and ultimately free it. If an error occurs at any point during the lifecycle of a particular xlog_recover, xlog_recover_process_data() frees the object and returns an error.

xlog_recover_commit_trans() handles the final processing of the transaction. It submits whatever I/O is required for the transaction and frees xlog_recover object along with the transaction items it tracks. If an error occurs at the final stages of the commit operation, such as I/O failure, both xlog_recover_commit_trans() and xlog_recover_process_data() attempt to free the trans object.

Modify xlog_recover_commit_trans() to only free the trans object on successful completion of the trans, including any I/O errors that might occur when recovering the log.

Signed-off-by Brian Foster <[email protected]>

---

Hi all,

I found that the recent buffer I/O rework fixes didn't address the crash reproduced by the dm-flakey/log recovery test case I posted recently. I tracked the crash down to this, which allows the test to pass. This addresses the crash I saw when running the reproducer manually with the metadump that Alex posted as well.

FWIW, I also went back and tested the xfs_buf_iowait() experiment in both scenarios (Alex's metadump and xfstests test) and they all reproduce the same crash for me. I think that either I'm still not reproducing the original problem, something else might have contaminated the original xfs_buf_iowait() test to give a false positive, or something else entirely is going on.

Alex,

Quoted 7 lines

If you have a chance, I think it might be interesting to see whether you reproduce any problems with this patch. It looks like this is a regression introduced by:

2a84108f xfs: free the list of recovery items on error

... but I have no idea if that's in whatever kernel you're running.

I am running kernel 3.8.13 with some changes (published at
https://github.com/zadarastorage/zadara-xfs-pushback), but this problem also happens on pristine 3.8.13 from
git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git,
branch linux-stable-3.8.y.

I do not have commit 2a84108f in this kernel. It was introduced in 3.14. I applied your patch to 3.8.13, but it doesn't fix the issue. Same problem happens when testing scenario that I described in
http://oss.sgi.com/pipermail/xfs/2014-August/037637.html.

Thanks,
Alex.

Quoted 28 lines

Brian

 fs/xfs/xfs_log_recover.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

fs/xfs/xfs_log_recover.c +8 -3

index 176c4b3..daca9a6 100644
@@ -3528,10 +3528,15 @@ out:
        if (!list_empty(&done_list))
                list_splice_init(&done_list, &trans->r_itemq);
 
-       xlog_recover_free_trans(trans);
-
        error2 = xfs_buf_delwri_submit(&buffer_list);
-       return error ? error : error2;
+
+       if (!error)
+               error = error2;
+       /* caller frees trans on error */
+       if (!error)
+               xlog_recover_free_trans(trans);
+
+       return error;
 }
 

Quoted 4 lines

fs/xfs/xfs_log_recover.c +0 -1

 STATIC int
--

1.8.3.1

Hi Brian, Dave,
I tested this patch on kernel 3.16, top commit:

commit 19583ca584d6f574384e17fe7613dfaeadcdc4a6

Author: Linus Torvalds <[email protected]>
Date:   Sun Aug 3 15:25:02 2014 -0700

   Linux 3.16

and, yes, it appears to fix the issue.

Trouble is that our production kernel is 3.8.13, and we cannot upgrade to mainline kernel easily. Question is whether we can expect some patch suitable for our kernel, or, since our kernel is EOL and not a long-term one, we cannot?

Thanks for your help,
Alex.

-----Original Message----- From: Brian Foster
Sent: 25 August, 2014 5:20 PM
To: Alex Lyakas
Cc: [email protected] ; Dave Chinner
Subject: Re: [PATCH] xfs: fix double free of trans in log recovery on I/O error

Quoted 61 lines · Alex Lyakas

Hi Brian,

Quoted 45 lines · Brian Foster

XFS log recovery builds up an xlog_recover object as it passes through the log operations on the physical log. These structures are managed via a hash table and are allocated when a new transaction is encountered and freed once a commit operation for the transaction is encountered.

This state machine for active transactions is implemented by a combination of xlog_do_recovery_pass(), which walks through the log buffers and xlog_recover_process_data() which processes log operations within each buffer. The latter function decides whether to allocate a new xlog_recover, add to it or commit and ultimately free it. If an error occurs at any point during the lifecycle of a particular xlog_recover, xlog_recover_process_data() frees the object and returns an error.

xlog_recover_commit_trans() handles the final processing of the transaction. It submits whatever I/O is required for the transaction and frees xlog_recover object along with the transaction items it tracks. If an error occurs at the final stages of the commit operation, such as I/O failure, both xlog_recover_commit_trans() and xlog_recover_process_data() attempt to free the trans object.

Modify xlog_recover_commit_trans() to only free the trans object on successful completion of the trans, including any I/O errors that might occur when recovering the log.

Signed-off-by Brian Foster <[email protected]>

---

Hi all,

I found that the recent buffer I/O rework fixes didn't address the crash reproduced by the dm-flakey/log recovery test case I posted recently. I tracked the crash down to this, which allows the test to pass. This addresses the crash I saw when running the reproducer manually with the metadump that Alex posted as well.

FWIW, I also went back and tested the xfs_buf_iowait() experiment in both scenarios (Alex's metadump and xfstests test) and they all reproduce the same crash for me. I think that either I'm still not reproducing the original problem, something else might have contaminated the original xfs_buf_iowait() test to give a false positive, or something else entirely is going on.

Alex,

Quoted 7 lines

If you have a chance, I think it might be interesting to see whether you reproduce any problems with this patch. It looks like this is a regression introduced by:

2a84108f xfs: free the list of recovery items on error

... but I have no idea if that's in whatever kernel you're running.

I am running kernel 3.8.13 with some changes (published at
https://github.com/zadarastorage/zadara-xfs-pushback), but this problem also happens on pristine 3.8.13 from
git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git,
branch linux-stable-3.8.y.

Quoted 5 lines

I do not have commit 2a84108f in this kernel. It was introduced in 3.14. I applied your patch to 3.8.13, but it doesn't fix the issue. Same problem happens when testing scenario that I described in
http://oss.sgi.com/pipermail/xfs/2014-August/037637.html.

Ok, thanks. Yeah, I don't see the double free regression in the 3.8.13 stable branch. I went back to that kernel to try and confirm some things. I do reproduce the problem with your metadump as well as the test case I put together. I tested Dave's buf hold across sync I/O patch and that does indeed prevent the problem.

For whatever reason, neither the test case nor your metadump reproduce the same problem on latest kernels. Instead, they reproduce this double free regression. I suspect this is what you ran into when you reproduced on a more recent kernel. If you'd like, feel free to try and verify that by running your reproducer again on a recent kernel with this patch and see if you can still reproduce a crash as with the 3.8.13 kernel.

Brian

Quoted 31 lines

Thanks,
Alex.

Quoted 28 lines

Brian

 fs/xfs/xfs_log_recover.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

fs/xfs/xfs_log_recover.c +8 -3

index 176c4b3..daca9a6 100644
@@ -3528,10 +3528,15 @@ out:
        if (!list_empty(&done_list))
                list_splice_init(&done_list, &trans->r_itemq);
 
-       xlog_recover_free_trans(trans);
-
        error2 = xfs_buf_delwri_submit(&buffer_list);
-       return error ? error : error2;
+
+       if (!error)
+               error = error2;
+       /* caller frees trans on error */
+       if (!error)
+               xlog_recover_free_trans(trans);
+
+       return error;
 }
 

Quoted 4 lines

Quoted 4 lines

fs/xfs/xfs_log_recover.c +0 -1

 STATIC int
--

1.8.3.1

Hi Brian, Dave,
I tested this patch on kernel 3.16, top commit:

commit 19583ca584d6f574384e17fe7613dfaeadcdc4a6

Author: Linus Torvalds <[email protected]>
Date:   Sun Aug 3 15:25:02 2014 -0700

   Linux 3.16

and, yes, it appears to fix the issue.

Trouble is that our production kernel is 3.8.13, and we cannot upgrade to mainline kernel easily. Question is whether we can expect some patch suitable for our kernel, or, since our kernel is EOL and not a long-term one, we cannot?

Thanks for your help,
Alex.

-----Original Message----- From: Brian Foster
Sent: 25 August, 2014 5:20 PM
To: Alex Lyakas
Cc: [email protected] ; Dave Chinner
Subject: Re: [PATCH] xfs: fix double free of trans in log recovery on I/O error

Quoted 61 lines · Alex Lyakas

Hi Brian,

Quoted 45 lines · Brian Foster

XFS log recovery builds up an xlog_recover object as it passes through the log operations on the physical log. These structures are managed via a hash table and are allocated when a new transaction is encountered and freed once a commit operation for the transaction is encountered.

This state machine for active transactions is implemented by a combination of xlog_do_recovery_pass(), which walks through the log buffers and xlog_recover_process_data() which processes log operations within each buffer. The latter function decides whether to allocate a new xlog_recover, add to it or commit and ultimately free it. If an error occurs at any point during the lifecycle of a particular xlog_recover, xlog_recover_process_data() frees the object and returns an error.

xlog_recover_commit_trans() handles the final processing of the transaction. It submits whatever I/O is required for the transaction and frees xlog_recover object along with the transaction items it tracks. If an error occurs at the final stages of the commit operation, such as I/O failure, both xlog_recover_commit_trans() and xlog_recover_process_data() attempt to free the trans object.

Modify xlog_recover_commit_trans() to only free the trans object on successful completion of the trans, including any I/O errors that might occur when recovering the log.

Signed-off-by Brian Foster <[email protected]>

---

Hi all,

I found that the recent buffer I/O rework fixes didn't address the crash reproduced by the dm-flakey/log recovery test case I posted recently. I tracked the crash down to this, which allows the test to pass. This addresses the crash I saw when running the reproducer manually with the metadump that Alex posted as well.

FWIW, I also went back and tested the xfs_buf_iowait() experiment in both scenarios (Alex's metadump and xfstests test) and they all reproduce the same crash for me. I think that either I'm still not reproducing the original problem, something else might have contaminated the original xfs_buf_iowait() test to give a false positive, or something else entirely is going on.

Alex,

Quoted 7 lines

If you have a chance, I think it might be interesting to see whether you reproduce any problems with this patch. It looks like this is a regression introduced by:

2a84108f xfs: free the list of recovery items on error

... but I have no idea if that's in whatever kernel you're running.

I am running kernel 3.8.13 with some changes (published at
https://github.com/zadarastorage/zadara-xfs-pushback), but this problem also happens on pristine 3.8.13 from
git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git,
branch linux-stable-3.8.y.

Quoted 5 lines

I do not have commit 2a84108f in this kernel. It was introduced in 3.14. I applied your patch to 3.8.13, but it doesn't fix the issue. Same problem happens when testing scenario that I described in
http://oss.sgi.com/pipermail/xfs/2014-August/037637.html.

Ok, thanks. Yeah, I don't see the double free regression in the 3.8.13 stable branch. I went back to that kernel to try and confirm some things. I do reproduce the problem with your metadump as well as the test case I put together. I tested Dave's buf hold across sync I/O patch and that does indeed prevent the problem.

For whatever reason, neither the test case nor your metadump reproduce the same problem on latest kernels. Instead, they reproduce this double free regression. I suspect this is what you ran into when you reproduced on a more recent kernel. If you'd like, feel free to try and verify that by running your reproducer again on a recent kernel with this patch and see if you can still reproduce a crash as with the 3.8.13 kernel.

Brian

Quoted 31 lines

Thanks,
Alex.

Quoted 28 lines

Brian

 fs/xfs/xfs_log_recover.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

fs/xfs/xfs_log_recover.c +8 -3

index 176c4b3..daca9a6 100644
@@ -3528,10 +3528,15 @@ out:
        if (!list_empty(&done_list))
                list_splice_init(&done_list, &trans->r_itemq);
 
-       xlog_recover_free_trans(trans);
-
        error2 = xfs_buf_delwri_submit(&buffer_list);
-       return error ? error : error2;
+
+       if (!error)
+               error = error2;
+       /* caller frees trans on error */
+       if (!error)
+               xlog_recover_free_trans(trans);
+
+       return error;
 }
 

Quoted 4 lines

Quoted 4 lines

fs/xfs/xfs_log_recover.c +0 -1

 STATIC int
--

1.8.3.1

Hi Brian, Dave,
I tested this patch on 3.8.13 kernel with the scenario I described in
http://oss.sgi.com/pipermail/xfs/2014-August/037637.html, but I still see the issue.
I placed the metadump at
https://drive.google.com/file/d/0ByBy89zr3kJNV2UxMERNTkE4aHM/edit?usp=sharing

During log recovery, 3 IO errors are encountered:

[  340.381199] XFS (dm-0): Mounting Filesystem
[  340.439897] XFS (dm-0): Sleep 10s before xlog_do_recover
[  350.440143] XFS (dm-0): Starting recovery (logdev: internal)
[  351.584647] XFS (dm-0): metadata I/O error: block 0x1
("xlog_recover_iodone") error 28 numblks 1
[  351.584660] XFS (dm-0): metadata I/O error: block 0x40
("xlog_recover_iodone") error 28 numblks 16
[  351.584665] XFS (dm-0): xfs_do_force_shutdown(0x1) called from line 377
of file /mnt/work/alex/zadara-btrfs/fs/xfs/xfs_log_recover.c.  Return
address = 0xffffffffa0372728
[  351.584969] XFS (dm-0): I/O Error Detected. Shutting down filesystem
[  351.584970] XFS (dm-0): Please umount the filesystem and rectify the
problem(s)
[  351.585047] XFS (dm-0): metadata I/O error: block 0x1e00040
("xlog_recover_iodone") error 28 numblks 16
[  351.585050] XFS (dm-0): xfs_do_force_shutdown(0x1) called from line 377
of file /mnt/work/alex/zadara-btrfs/fs/xfs/xfs_log_recover.c.  Return
address = 0xffffffffa0372728
[  351.585068] XFS (dm-0): log mount/recovery failed: error 28
[  351.585332] XFS (dm-0): log mount failed

Two IO error callbacks are handled before XFS is unmounted, but the last one crashes with stack[1].

Do I need some or all of the 9 patches that Dave posted? (They do not apply to my kernel, so I need to apply them by hand).

Thanks,
Alex.

[1]

[  351.592349] general protection fault: 0000 [#1] SMP
[  351.593440] Modules linked in: xfs(O) libcrc32c dm_linear_custom(O) nfsv3

deflate zlib_deflate ctr twofish_generic twofish_x86_64_3way glue_helper lrw xts gf128mul twofish_x86_64 twofish_common camellia_generic serpent_generic blowfish_generic blowfish_x86_64 blowfish_common cast5_generic cast_common des_generic xcbc rmd160 sha512_generic crypto_null af_key xfrm_algo kvm ppdev vfat fat dm_round_robin microcode nfsd nfs_acl parport_pc dm_iostat(O) dm_multipath(O) psmouse serio_raw mac_hid i2c_piix4 lp parport nfsv4 auth_rpcgss nfs fscache lockd sunrpc floppy

[  351.596118] CPU 3
[  351.596118] Pid: 133, comm: kworker/3:1H Tainted: G        W  O
3.8.13-557-generic #1382000791 Bochs Bochs
[  351.596118] RIP: 0010:[<ffffffff8133c2cb>]  [<ffffffff8133c2cb>]
strnlen+0xb/0x30
[  351.596118] RSP: 0018:ffff880035405b08  EFLAGS: 00010086
[  351.596118] RAX: 0000000000000000 RBX: ffffffff81e6a4e7 RCX:
0000000000000000
[  351.596118] RDX: e4e8390a265c0000 RSI: ffffffffffffffff RDI:
e4e8390a265c0000
[  351.596118] RBP: ffff880035405b08 R08: 000000000000ffff R09:
000000000000ffff
[  351.596118] R10: 0000000000000000 R11: 0000000000000331 R12:
e4e8390a265c0000
[  351.596118] R13: ffffffff81e6a8c0 R14: 0000000000000000 R15:
000000000000ffff
[  351.596118] FS:  0000000000000000(0000) GS:ffff88007fd80000(0000)
knlGS:0000000000000000
[  351.596118] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  351.596118] CR2: 00007fff7bfe1c38 CR3: 0000000035a59000 CR4:
00000000000006e0
[  351.596118] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[  351.596118] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
0000000000000400
[  351.596118] Process kworker/3:1H (pid: 133, threadinfo ffff880035404000,
task ffff880035ae5c00)
[  351.596118] Stack:
[  351.596118]  ffff880035405b48 ffffffff8133dd5e ffff880035405b28
ffffffff81e6a4e7
[  351.596118]  ffffffffa03b2bc4 ffff880035405c80 ffffffffa03b2bc4
ffffffff81e6a8c0
[  351.596118]  ffff880035405bc8 ffffffff8133ef59 ffff880035405bc8
ffffffff81059aa7
[  351.596118] Call Trace:
[  351.596118]  [<ffffffff8133dd5e>] string.isra.4+0x3e/0xd0
[  351.596118]  [<ffffffff8133ef59>] vsnprintf+0x219/0x640
[  351.596118]  [<ffffffff81059aa7>] ? msg_print_text+0xb7/0x1b0
[  351.596118]  [<ffffffff8133f441>] vscnprintf+0x11/0x30
[  351.596118]  [<ffffffff8105a971>] vprintk_emit+0xc1/0x490
[  351.596118]  [<ffffffff8105aa20>] ? vprintk_emit+0x170/0x490
[  351.596118]  [<ffffffff8168b992>] printk+0x61/0x63
[  351.596118]  [<ffffffffa0335ba1>] __xfs_printk+0x31/0x50 [xfs]
[  351.596118]  [<ffffffffa0335df3>] xfs_notice+0x53/0x60 [xfs]
[  351.596118]  [<ffffffffa032cbc5>] xfs_do_force_shutdown+0xf5/0x180 [xfs]
[  351.596118]  [<ffffffffa0372728>] ? xlog_recover_iodone+0x48/0x70 [xfs]
[  351.596118]  [<ffffffffa0372728>] xlog_recover_iodone+0x48/0x70 [xfs]
[  351.596118]  [<ffffffffa032245d>] xfs_buf_iodone_work+0x4d/0xb0 [xfs]
[  351.596118]  [<ffffffff81077a11>] process_one_work+0x141/0x4a0
[  351.596118]  [<ffffffff810789e8>] worker_thread+0x168/0x410
[  351.596118]  [<ffffffff81078880>] ? manage_workers+0x120/0x120
[  351.596118]  [<ffffffff8107df10>] kthread+0xc0/0xd0
[  351.596118]  [<ffffffff8107de50>] ? flush_kthread_worker+0xb0/0xb0
[  351.596118]  [<ffffffff816ab86c>] ret_from_fork+0x7c/0xb0
[  351.596118]  [<ffffffff8107de50>] ? flush_kthread_worker+0xb0/0xb0
[  351.596118] Code: 31 c0 80 3f 00 55 48 89 e5 74 11 48 89 f8 66 90 48 83
c0 01 80 38 00 75 f7 48 29 f8 5d c3 66 90 55 31 c0 48 85 f6 48 89 e5 74 23
<80> 3f 00 74 1e 48 89 f8 eb 0c 0f 1f 00 48 83 ee 01 80 38 00 74
[  351.596118] RIP  [<ffffffff8133c2cb>] strnlen+0xb/0x30
[  351.596118]  RSP <ffff880035405b08>
[  351.596118] ---[ end trace cb6b9820566f6848 ]---

-----Original Message----- From: Brian Foster
Sent: 01 September, 2014 12:05 AM
To: Alex Lyakas
Cc: [email protected] ; Dave Chinner
Subject: Re: [PATCH] xfs: fix double free of trans in log recovery on I/O error

Quoted 11 lines · Alex Lyakas

Hi Brian, Dave,
I tested this patch on kernel 3.16, top commit:

commit 19583ca584d6f574384e17fe7613dfaeadcdc4a6

Author: Linus Torvalds <[email protected]>
Date:   Sun Aug 3 15:25:02 2014 -0700

Linux 3.16

and, yes, it appears to fix the issue.

Thanks. That settles that then, I think. We're reproducing different problems on the 3.8 stable kernel vs. a recent kernel using the same test case.

Quoted 5 lines

Trouble is that our production kernel is 3.8.13, and we cannot upgrade to mainline kernel easily. Question is whether we can expect some patch suitable for our kernel, or, since our kernel is EOL and not a long-term one, we cannot?

Dave wrote a patch specifically to resolve this problem on older kernels:

http://oss.sgi.com/archives/xfs/2014-08/msg00204.html

Brian

Quoted 134 lines

Thanks for your help,
Alex.

-----Original Message----- From: Brian Foster
Sent: 25 August, 2014 5:20 PM
To: Alex Lyakas
Cc: [email protected] ; Dave Chinner
Subject: Re: [PATCH] xfs: fix double free of trans in log recovery on I/O error

Quoted 6 lines · Alex Lyakas

Hi Brian,

Quoted 2 lines · Brian Foster

XFS log recovery builds up an xlog_recover object as it passes through the log operations on the physical log. These structures are managed >>

via

Quoted 1 line

Quoted 1 line

a hash table and are allocated when a new transaction is encountered >>

and

Quoted 11 lines

Quoted 11 lines

freed once a commit operation for the transaction is encountered.

This state machine for active transactions is implemented by a combination of xlog_do_recovery_pass(), which walks through the log buffers and xlog_recover_process_data() which processes log operations within each buffer. The latter function decides whether to allocate a new xlog_recover, add to it or commit and ultimately free it. If an error occurs at any point during the lifecycle of a particular xlog_recover, xlog_recover_process_data() frees the object and returns an error.

Quoted 2 lines

Quoted 2 lines

xlog_recover_commit_trans() handles the final processing of the transaction. It submits whatever I/O is required for the transaction >>

and

Quoted 3 lines

Quoted 3 lines

frees xlog_recover object along with the transaction items it tracks. If
an error occurs at the final stages of the commit operation, such as >>

I/O

Quoted 7 lines

Quoted 7 lines

failure, both xlog_recover_commit_trans() and xlog_recover_process_data() attempt to free the trans object.

Modify xlog_recover_commit_trans() to only free the trans object on successful completion of the trans, including any I/O errors that might occur when recovering the log.

Quoted 6 lines

Quoted 6 lines

Signed-off-by Brian Foster <[email protected]>

---

Hi all,

I found that the recent buffer I/O rework fixes didn't address the >>

crash

Quoted 9 lines

Quoted 9 lines

reproduced by the dm-flakey/log recovery test case I posted recently. I tracked the crash down to this, which allows the test to pass. This addresses the crash I saw when running the reproducer manually with the metadump that Alex posted as well.

FWIW, I also went back and tested the xfs_buf_iowait() experiment in both scenarios (Alex's metadump and xfstests test) and they all reproduce the same crash for me. I think that either I'm still not reproducing the original problem, something else might have >>

contaminated

Quoted 6 lines

Quoted 6 lines

the original xfs_buf_iowait() test to give a false positive, or something else entirely is going on.

Alex,

If you have a chance, I think it might be interesting to see whether >>

you

Quoted 12 lines

Quoted 6 lines

reproduce any problems with this patch. It looks like this is a regression introduced by:

2a84108f xfs: free the list of recovery items on error

... but I have no idea if that's in whatever kernel you're running.

I am running kernel 3.8.13 with some changes (published at
https://github.com/zadarastorage/zadara-xfs-pushback), but this problem also happens on pristine 3.8.13 from
git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git,
branch linux-stable-3.8.y.

Quoted 5 lines

I do not have commit 2a84108f in this kernel. It was introduced in 3.14. I applied your patch to 3.8.13, but it doesn't fix the issue. Same problem happens when testing scenario that I described in
http://oss.sgi.com/pipermail/xfs/2014-August/037637.html.

Ok, thanks. Yeah, I don't see the double free regression in the 3.8.13 stable branch. I went back to that kernel to try and confirm some things. I do reproduce the problem with your metadump as well as the test case I put together. I tested Dave's buf hold across sync I/O patch and that does indeed prevent the problem.

For whatever reason, neither the test case nor your metadump reproduce the same problem on latest kernels. Instead, they reproduce this double free regression. I suspect this is what you ran into when you reproduced on a more recent kernel. If you'd like, feel free to try and verify that by running your reproducer again on a recent kernel with this patch and see if you can still reproduce a crash as with the 3.8.13 kernel.

Brian

Quoted 31 lines

Thanks,
Alex.

Quoted 28 lines

Brian

 fs/xfs/xfs_log_recover.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

fs/xfs/xfs_log_recover.c +8 -3

index 176c4b3..daca9a6 100644
@@ -3528,10 +3528,15 @@ out:
        if (!list_empty(&done_list))
                list_splice_init(&done_list, &trans->r_itemq);
 
-       xlog_recover_free_trans(trans);
-
        error2 = xfs_buf_delwri_submit(&buffer_list);
-       return error ? error : error2;
+
+       if (!error)
+               error = error2;
+       /* caller frees trans on error */
+       if (!error)
+               xlog_recover_free_trans(trans);
+
+       return error;
 }
 

Quoted 5 lines

Quoted 4 lines

Quoted 4 lines

fs/xfs/xfs_log_recover.c +0 -1

 STATIC int
--

1.8.3.1

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Hi Brian, Dave,
I tested this patch on 3.8.13 kernel with the scenario I described
in http://oss.sgi.com/pipermail/xfs/2014-August/037637.html, but I
still see the issue.
I placed the metadump at https://drive.google.com/file/d/0ByBy89zr3kJNV2UxMERNTkE4aHM/edit?usp=sharing

During log recovery, 3 IO errors are encountered:

[  340.381199] XFS (dm-0): Mounting Filesystem
[  340.439897] XFS (dm-0): Sleep 10s before xlog_do_recover
[  350.440143] XFS (dm-0): Starting recovery (logdev: internal)
[  351.584647] XFS (dm-0): metadata I/O error: block 0x1
("xlog_recover_iodone") error 28 numblks 1
[  351.584660] XFS (dm-0): metadata I/O error: block 0x40
("xlog_recover_iodone") error 28 numblks 16
[  351.584665] XFS (dm-0): xfs_do_force_shutdown(0x1) called from
line 377 of file
/mnt/work/alex/zadara-btrfs/fs/xfs/xfs_log_recover.c.  Return
address = 0xffffffffa0372728
[  351.584969] XFS (dm-0): I/O Error Detected. Shutting down filesystem
[  351.584970] XFS (dm-0): Please umount the filesystem and rectify
the problem(s)
[  351.585047] XFS (dm-0): metadata I/O error: block 0x1e00040
("xlog_recover_iodone") error 28 numblks 16
[  351.585050] XFS (dm-0): xfs_do_force_shutdown(0x1) called from
line 377 of file
/mnt/work/alex/zadara-btrfs/fs/xfs/xfs_log_recover.c.  Return
address = 0xffffffffa0372728
[  351.585068] XFS (dm-0): log mount/recovery failed: error 28
[  351.585332] XFS (dm-0): log mount failed

Two IO error callbacks are handled before XFS is unmounted, but the last one crashes with stack[1].

Do I need some or all of the 9 patches that Dave posted? (They do not apply to my kernel, so I need to apply them by hand).

Quoted 5 lines · Alex Lyakas

Hi Brian, Dave,
I tested this patch on 3.8.13 kernel with the scenario I described in http://oss.sgi.com/pipermail/xfs/2014-August/037637.html, but I still see the issue.
I placed the metadump at

https://drive.google.com/file/d/0ByBy89zr3kJNV2UxMERNTkE4aHM/edit?usp=sharing

Quoted 28 lines

During log recovery, 3 IO errors are encountered:

[  340.381199] XFS (dm-0): Mounting Filesystem
[  340.439897] XFS (dm-0): Sleep 10s before xlog_do_recover
[  350.440143] XFS (dm-0): Starting recovery (logdev: internal)
[  351.584647] XFS (dm-0): metadata I/O error: block 0x1
("xlog_recover_iodone") error 28 numblks 1
[  351.584660] XFS (dm-0): metadata I/O error: block 0x40
("xlog_recover_iodone") error 28 numblks 16
[  351.584665] XFS (dm-0): xfs_do_force_shutdown(0x1) called from
line 377 of file
/mnt/work/alex/zadara-btrfs/fs/xfs/xfs_log_recover.c.  Return
address = 0xffffffffa0372728
[  351.584969] XFS (dm-0): I/O Error Detected. Shutting down filesystem
[  351.584970] XFS (dm-0): Please umount the filesystem and rectify
the problem(s)
[  351.585047] XFS (dm-0): metadata I/O error: block 0x1e00040
("xlog_recover_iodone") error 28 numblks 16
[  351.585050] XFS (dm-0): xfs_do_force_shutdown(0x1) called from
line 377 of file
/mnt/work/alex/zadara-btrfs/fs/xfs/xfs_log_recover.c.  Return
address = 0xffffffffa0372728
[  351.585068] XFS (dm-0): log mount/recovery failed: error 28
[  351.585332] XFS (dm-0): log mount failed

Two IO error callbacks are handled before XFS is unmounted, but the last one crashes with stack[1].

Quoted 2 lines

Do I need some or all of the 9 patches that Dave posted? (They do not apply to my kernel, so I need to apply them by hand).

No, I suspect that there are other problems that have been fixed since 3.8 that you are missing. e.g.

9c23ecc xfs: unmount does not wait for shutdown during unmount

THere's bound to be others, so you're really going to need to look at the differences between 3.8 and a current mainline to determine what other patches you are going to need...

Cheers,

Dave.
--
Dave Chinner
[email protected]