Uploaded image for project: 'Cassandra'
  1. Cassandra
  2. CASSANDRA-8019

Windows Unit tests and Dtests erroring due to sstable deleting task error

    Details

      Description

      Currently a large number of dtests and unit tests are erroring on windows with the following error in the node log:

      ERROR [NonPeriodicTasks:1] 2014-09-29 11:05:04,383 SSTableDeletingTask.java:89 - Unable to delete c:\\users\\username\\appdata\\local\\temp\\dtest-vr6qgw\\test\\node1\\data\\system\\local-7ad54392bcdd35a684174e047860b377\\system-local-ka-4-Data.db (it will be removed on server restart; we'll also retry after GC)\n
      

      git bisect points to the following commit:

      0e831007760bffced8687f51b99525b650d7e193 is the first bad commit
      commit 0e831007760bffced8687f51b99525b650d7e193
      Author: Benedict Elliott Smith <benedict@apache.org>
      Date:  Fri Sep 19 18:17:19 2014 +0100
      
          Fix resource leak in event of corrupt sstable
      
          patch by benedict; review by yukim for CASSANDRA-7932
      
      :100644 100644 d3ee7d99179dce03307503a8093eb47bd0161681 f55e5d27c1c53db3485154cd16201fc5419f32df M      CHANGES.txt
      :040000 040000 194f4c0569b6be9cc9e129c441433c5c14de7249 3c62b53b2b2bd4b212ab6005eab38f8a8e228923 M  src
      :040000 040000 64f49266e328b9fdacc516c52ef1921fe42e994f de2ca38232bee6d2a6a5e068ed9ee0fbbc5aaebe M  test
      

      You can reproduce this by running simple_bootstrap_test.

      1. 8019_v3.txt
        18 kB
        Joshua McKenzie
      2. 8019_v2.txt
        2 kB
        Joshua McKenzie
      3. 8019_conservative_v1.txt
        12 kB
        Joshua McKenzie
      4. 8019_aggressive_v1.txt
        1 kB
        Joshua McKenzie

        Issue Links

          Activity

          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment - - edited

          Trunk isn't having any issues so this is probably related to the FILE_SHARE_DELETE flag problems we addressed with CASSANDRA-4050. Also - simple unit tests are failing on Windows w/this in 2.1 branch so no need to go so far as dtesting to reproduce.

          edit: I should mention - a cursory inspection of the changes in here look like the try w/resources idiom should have closed the ScannerList references as expected. Benedict: any initial thoughts, other than those that led to CASSANDRA-7705?

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - - edited Trunk isn't having any issues so this is probably related to the FILE_SHARE_DELETE flag problems we addressed with CASSANDRA-4050 . Also - simple unit tests are failing on Windows w/this in 2.1 branch so no need to go so far as dtesting to reproduce. edit: I should mention - a cursory inspection of the changes in here look like the try w/resources idiom should have closed the ScannerList references as expected. Benedict : any initial thoughts, other than those that led to CASSANDRA-7705 ?
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment -

          We open handles to the index file and data file within an SSTableScanner and aren't participating in SSTR refcounting. SSTR.releaseReference attempts to delete these two files within the SSTableDeletingTask, giving rise to the error messages we're seeing when there's still SSTableScanners with those files open. This doesn't present on trunk in windows as FILE_SHARE_DELETE w/nio.2 allows files to be deleted w/other handles open to them transparently as in linux.

          w/regards to this particular patch introducing (more) errors related to compaction and sstable deletion, it's a timing issue and there's a few ways I've experimented with to address this. All of them work but have different compromises. In order of least to most invasive:

          1. roll back the scoped-resource access in CompactionTask and target a scanners.close() right before
            cfs.getDataTracker().markCompactedSSTablesReplaced(oldSStables, newSStables, compactionType);

            This partially defeats the purpose of the earlier patch.

          2. move the call to markCompactedSSTablesReplaced to the end of CompactionTask.runWith after closing scope on the try block that opened them. This potentially delays said marking until stat calculation and logging is completed but scopes the resource access.
          3. have SSTableScanners acquireReference() and releaseReference() on their parent sstables on ctor and close() calls respectively

          I have mixed feelings about all three options. I feel like option #3 is the most "correct" approach but it's also the most heavyweight by far and most prone to introduction of subtle bugs as it's imposing a new constraint on ref counting w/regards to SSTableScanner lifetimes. With regard to us trying to tighten up and reduce manual ref-counting this approach also feels like a significant step back.

          For now (in 2.1.X land), I'm comfortable with rolling back the try w/resource usage on CompactionTask.runWith and then we think about this further, perhaps in a separate ticket if we feel it warranted. Digging into the unit tests on the 2.1 branch, it's apparent that this type of problem is pretty widespread on Windows as I get the same failures in many other unit tests (as far back as pre CASSANDRA-6916 days). We may need to file these errors under "Cassandra-2.1 on Windows is beta, this is fixed on trunk", keeping in mind that these issues resolve once the scanners are closed. Might be worth considering dropping the logging severity on deletion failure from error to warn as it's going to be common on 2.1 currently.

          Having said that - option 3 has a pretty profound impact on the 2.1 branch w/regards to Windows:

          $ grep 'Unable to delete' 2.1_head.testresults | wc -l
          7860
          
          $ grep 'Unable to delete' opt3_heavy.testresults | wc -l
          2
          

          We go from 9 actual test failures to 8 w/this change on Windows, and all currently passing unit tests continue to pass as expected on linux. I put in some logic to check if we use an SSTableScanner after the corresponding SSTR goes through the tidy process and, at least in all our unit tests, we don't appear to try and use a scanner after deleting the underlying SSTR.

          Attaching both a conservative (option 1) and invasive (option 3) patch. My vote's for 1 but think there's merit in considering the implications of 3 and our current refcounting (and the meta purpose it serves).

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - We open handles to the index file and data file within an SSTableScanner and aren't participating in SSTR refcounting. SSTR.releaseReference attempts to delete these two files within the SSTableDeletingTask, giving rise to the error messages we're seeing when there's still SSTableScanners with those files open. This doesn't present on trunk in windows as FILE_SHARE_DELETE w/nio.2 allows files to be deleted w/other handles open to them transparently as in linux. w/regards to this particular patch introducing (more) errors related to compaction and sstable deletion, it's a timing issue and there's a few ways I've experimented with to address this. All of them work but have different compromises. In order of least to most invasive: roll back the scoped-resource access in CompactionTask and target a scanners.close() right before cfs.getDataTracker().markCompactedSSTablesReplaced(oldSStables, newSStables, compactionType); This partially defeats the purpose of the earlier patch. move the call to markCompactedSSTablesReplaced to the end of CompactionTask.runWith after closing scope on the try block that opened them. This potentially delays said marking until stat calculation and logging is completed but scopes the resource access. have SSTableScanners acquireReference() and releaseReference() on their parent sstables on ctor and close() calls respectively I have mixed feelings about all three options. I feel like option #3 is the most "correct" approach but it's also the most heavyweight by far and most prone to introduction of subtle bugs as it's imposing a new constraint on ref counting w/regards to SSTableScanner lifetimes. With regard to us trying to tighten up and reduce manual ref-counting this approach also feels like a significant step back. For now (in 2.1.X land), I'm comfortable with rolling back the try w/resource usage on CompactionTask.runWith and then we think about this further, perhaps in a separate ticket if we feel it warranted. Digging into the unit tests on the 2.1 branch, it's apparent that this type of problem is pretty widespread on Windows as I get the same failures in many other unit tests (as far back as pre CASSANDRA-6916 days). We may need to file these errors under "Cassandra-2.1 on Windows is beta, this is fixed on trunk", keeping in mind that these issues resolve once the scanners are closed. Might be worth considering dropping the logging severity on deletion failure from error to warn as it's going to be common on 2.1 currently. Having said that - option 3 has a pretty profound impact on the 2.1 branch w/regards to Windows: $ grep 'Unable to delete' 2.1_head.testresults | wc -l 7860 $ grep 'Unable to delete' opt3_heavy.testresults | wc -l 2 We go from 9 actual test failures to 8 w/this change on Windows, and all currently passing unit tests continue to pass as expected on linux. I put in some logic to check if we use an SSTableScanner after the corresponding SSTR goes through the tidy process and, at least in all our unit tests, we don't appear to try and use a scanner after deleting the underlying SSTR. Attaching both a conservative (option 1) and invasive (option 3) patch. My vote's for 1 but think there's merit in considering the implications of 3 and our current refcounting (and the meta purpose it serves).
          Hide
          philipthompson Philip Thompson added a comment -

          This appears to be affecting 2.0-HEAD as well.

          Show
          philipthompson Philip Thompson added a comment - This appears to be affecting 2.0-HEAD as well.
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment -

          After chewing on this a bit, I've come to the conclusion that the problem here isn't really the order of deletion or even the pre-3.0 behavior as those files are eventually successfully deleted on a subsequent GC. Our problem is that we're logging this as an error immediately on 1st failure on Windows when we expect there to be some contention on ordering pre-CASSANDRA-4050 and it's not really an error condition.

          Having said that, we want to still log on legitimate error conditions so suppressing or dropping to WARN wouldn't be appropriate in those cases.

          I've attached a v2 patch against 2.0 that adds a retryCount to our SSTableDeletingTask that will print the error message after 3 failed deletion attempts and reset the counter, only if on Windows. Behavior on Linux remains at 1 failed deletion == logged. v2 quiets all deletion errors in unit tests on 2.0 and 2.1 but should leave room for genuine locked / undeletable files to log after a few failures. I should note: 3 is a completely arbitrary number, and relying on GC for eventual file deletion is of course not ideal.

          Thoughts Jonathan Ellis? I'd prefer we nip this in the bud as this 'Unable to delete' error is getting more prevalent on the 2.1 branch as we make further changes and optimizations, and I'm more comfortable loosening up the logging criteria for this error than retrofitting more reference counting or making changes to scanner close ordering throughout the code-base.

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - After chewing on this a bit, I've come to the conclusion that the problem here isn't really the order of deletion or even the pre-3.0 behavior as those files are eventually successfully deleted on a subsequent GC. Our problem is that we're logging this as an error immediately on 1st failure on Windows when we expect there to be some contention on ordering pre- CASSANDRA-4050 and it's not really an error condition. Having said that, we want to still log on legitimate error conditions so suppressing or dropping to WARN wouldn't be appropriate in those cases. I've attached a v2 patch against 2.0 that adds a retryCount to our SSTableDeletingTask that will print the error message after 3 failed deletion attempts and reset the counter, only if on Windows. Behavior on Linux remains at 1 failed deletion == logged. v2 quiets all deletion errors in unit tests on 2.0 and 2.1 but should leave room for genuine locked / undeletable files to log after a few failures. I should note: 3 is a completely arbitrary number, and relying on GC for eventual file deletion is of course not ideal. Thoughts Jonathan Ellis ? I'd prefer we nip this in the bud as this 'Unable to delete' error is getting more prevalent on the 2.1 branch as we make further changes and optimizations, and I'm more comfortable loosening up the logging criteria for this error than retrofitting more reference counting or making changes to scanner close ordering throughout the code-base.
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment -

          Slight tweak to v2 logging message.

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - Slight tweak to v2 logging message.
          Hide
          jbellis Jonathan Ellis added a comment -

          IIRC the current logic is, we refcount sstables on read. Compaction + drop assumes that if refcount is zero it's safe to delete. Meanwhile, "markCompaction" ensures we don't have multiple threads trying to compact the same sstable.

          How are we getting into a situation where SSTableScanner (used by compaction) still has it open when it's deleted?

          Show
          jbellis Jonathan Ellis added a comment - IIRC the current logic is, we refcount sstables on read. Compaction + drop assumes that if refcount is zero it's safe to delete. Meanwhile, "markCompaction" ensures we don't have multiple threads trying to compact the same sstable. How are we getting into a situation where SSTableScanner (used by compaction) still has it open when it's deleted?
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment -

          Compaction + drop assumes that if refcount is zero it's safe to delete.

          It does, however unless we can guarantee that all SSTableScanners are closed with handles to the underlying files this is an incorrect assumption (on Windows, pre 3.0)

          How are we getting into a situation where SSTableScanner (used by compaction) still has it open when it's deleted?

          Previously (before CASSANDRA-7932) we used a CloseableIterator and closed both that and the CompactionController prior to DataTracker.markCompactedSSTablesReplaced. Currently we're managing the controller and scanners via scoped-resource management within CompactionTask and calling markCompactedSSTablesReplaced before either are closed out. This marks the sstables obsolete, decrements ref count, and attempts to delete them while we still have the index and data file explicitly open in the scanners.

          Fixing the ordering in CompactionTask fixes the error this ticket was opened for but doesn't address all instances of these types of errors in unit tests on the 2.1 branch on Windows. I can play whac-a-mole tracking all of these down but there's nothing stopping us from re-introducing further errors of this type since there's no contract between the readers and scanners as far as references to underlying files is concerned. On 2.1+linux or trunk+either, you'll never see anything indicating that this ordering problem has occurred.

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - Compaction + drop assumes that if refcount is zero it's safe to delete. It does, however unless we can guarantee that all SSTableScanners are closed with handles to the underlying files this is an incorrect assumption (on Windows, pre 3.0) How are we getting into a situation where SSTableScanner (used by compaction) still has it open when it's deleted? Previously (before CASSANDRA-7932 ) we used a CloseableIterator and closed both that and the CompactionController prior to DataTracker.markCompactedSSTablesReplaced. Currently we're managing the controller and scanners via scoped-resource management within CompactionTask and calling markCompactedSSTablesReplaced before either are closed out. This marks the sstables obsolete, decrements ref count, and attempts to delete them while we still have the index and data file explicitly open in the scanners. Fixing the ordering in CompactionTask fixes the error this ticket was opened for but doesn't address all instances of these types of errors in unit tests on the 2.1 branch on Windows. I can play whac-a-mole tracking all of these down but there's nothing stopping us from re-introducing further errors of this type since there's no contract between the readers and scanners as far as references to underlying files is concerned. On 2.1+linux or trunk+either, you'll never see anything indicating that this ordering problem has occurred.
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment -

          How do you want to move forward on this Jonathan Ellis? I'm fine w/either the looser restrictions on logging on Windows or using these unit test errors to track down existing out-of-order problems in the code-base, but if we go the latter route I think we should figure out a way to tie the scanners to their underlying sstr. Whether that's integrating with the existing ref-counting logic or something else, I don't yet have a strong opinion.

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - How do you want to move forward on this Jonathan Ellis ? I'm fine w/either the looser restrictions on logging on Windows or using these unit test errors to track down existing out-of-order problems in the code-base, but if we go the latter route I think we should figure out a way to tie the scanners to their underlying sstr. Whether that's integrating with the existing ref-counting logic or something else, I don't yet have a strong opinion.
          Hide
          jbellis Jonathan Ellis added a comment -

          Long term, I'd really like to get rid of the rescheduling-failed-deletes hack in favor of fixing the ordering. As you point out, the problem with covering up known problems like this is, it can cover up unknown problems too.

          My preference would be to not suppress error logging in the meantime, but if that's scaring people away from trying it then I give it my blessing.

          Show
          jbellis Jonathan Ellis added a comment - Long term, I'd really like to get rid of the rescheduling-failed-deletes hack in favor of fixing the ordering. As you point out, the problem with covering up known problems like this is, it can cover up unknown problems too. My preference would be to not suppress error logging in the meantime, but if that's scaring people away from trying it then I give it my blessing.
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment -

          Well, it's not really a 'problem' with ordering as the handles are fine being open / scanned / read by other pid/tid's on linux and trunk w/Windows after another's deleted the underlying. It's really only a transient issue specific to the 2.1 branch on Windows.

          Regarding removing the rescheduling hack: I'm +1 to that as well, but we have that in there not just for dealing with legacy Windows I/O problems but also unmapping on non-Sun VM's. Even after 3.0 w/Windows fixes I don't know that we'll be able to get rid of SSTableDeletingTask unless we either remove mmap support or can guarantee that the un-mapping process is normalized / 'non-unsafe' on all VM's at that point.

          I'll put the suppression code in the 2.1 branch, remove on merge to trunk, and comment it appropriately. Not sure if this is scaring people away or not but it's certainly making QA's life a little harder since all the utest / dtests complain with that 'ERROR' in the logs.

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - Well, it's not really a 'problem' with ordering as the handles are fine being open / scanned / read by other pid/tid's on linux and trunk w/Windows after another's deleted the underlying. It's really only a transient issue specific to the 2.1 branch on Windows. Regarding removing the rescheduling hack: I'm +1 to that as well, but we have that in there not just for dealing with legacy Windows I/O problems but also unmapping on non-Sun VM's. Even after 3.0 w/Windows fixes I don't know that we'll be able to get rid of SSTableDeletingTask unless we either remove mmap support or can guarantee that the un-mapping process is normalized / 'non-unsafe' on all VM's at that point. I'll put the suppression code in the 2.1 branch, remove on merge to trunk, and comment it appropriately. Not sure if this is scaring people away or not but it's certainly making QA's life a little harder since all the utest / dtests complain with that 'ERROR' in the logs.
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment -

          Just to confirm before I commit and put you down as having reviewed - you're a grudging +1 on the _v2 patch as an interim solution on the 2.1 branch?

          Suppose I could put "blessed by jbellis" in commit notes...

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - Just to confirm before I commit and put you down as having reviewed - you're a grudging +1 on the _v2 patch as an interim solution on the 2.1 branch? Suppose I could put "blessed by jbellis" in commit notes...
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment -

          Discussed this offline - I'm going to pursue formalizing the relationship between SSTableScanners and SSTableReaders w/expectations of ordering, as we don't want to close out SSTR w/scanners still open to them (in general principle, though it doesn't seem to be hurting anything at this time). Currently in the 2.1 branch, Windows' intolerance of deletion of files w/open filehandles gives us a temporary "canary in a coal mine" on these specific ordering issues but we shouldn't rely on that, and that goes away in 3.0 anyway.

          My gut feeling is that codifying the expectation of release/deletion ordering is best served by _aggressive_v1 but I'm loathe to add more users of the ref counting mechanism on SSTR as it's been such a pain point for us.

          I've also created CASSANDRA-8271 to cover SSTableDeletingTask removal in 3.0.

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - Discussed this offline - I'm going to pursue formalizing the relationship between SSTableScanners and SSTableReaders w/expectations of ordering, as we don't want to close out SSTR w/scanners still open to them (in general principle, though it doesn't seem to be hurting anything at this time). Currently in the 2.1 branch, Windows' intolerance of deletion of files w/open filehandles gives us a temporary "canary in a coal mine" on these specific ordering issues but we shouldn't rely on that, and that goes away in 3.0 anyway. My gut feeling is that codifying the expectation of release/deletion ordering is best served by _aggressive_v1 but I'm loathe to add more users of the ref counting mechanism on SSTR as it's been such a pain point for us. I've also created CASSANDRA-8271 to cover SSTableDeletingTask removal in 3.0.
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment - - edited

          v3 attached. Refcounting on SSTR from within SSTableScanner, updated SSTableRewriterTest to try-with-resource CompactionControllers and Scanners. Passes all unit tests on linux and dtest failures match CI environment, and "Unable to delete" errors on windows unit tests on 2.1 branch are greatly reduced. I still see some "Unable to delete" messages during runtime while attempting to force compaction on a loaded system but those are also reduced and I'll track them down in a separate effort.

          I chose to go with refcounting rather than simply changing the ordering in CompactionTask as we need some codification of the ordering relationship between scanners and sstables in order to prevent this type of "error" in the future.

          The SSTableScanner relies on internal data structures within the SSTR and, while the previous code will hold the reference open and prevent GC due to the pointer it has internally as well as the ifile and dfile references, our previous logical structure of there being no relationship between SSTableScanners being open and SSTR deletion was misleading. While we replicate some of the references in the scanner so the SSTR can technically be deleted out of order and we rely on the filesystem to keep the file open if we have a handle to it, a more clear relationship between the components is preferable IMO.

          Jonathan Ellis: I threw you on this as reviewer when I was leaning towards log suppression route as it was a trivial effort; Marcus Eriksson: would you be willing to review this as you've been in the compaction and SSTableRewriter space recently?

          Edit: I should note: While this is a symptom that we see on Windows on the 2.1 branch specifically, this isn't so much a Windows issue as resource ordering issue centered around the compaction process and SSTableScanners.

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - - edited v3 attached. Refcounting on SSTR from within SSTableScanner, updated SSTableRewriterTest to try-with-resource CompactionControllers and Scanners. Passes all unit tests on linux and dtest failures match CI environment, and "Unable to delete" errors on windows unit tests on 2.1 branch are greatly reduced. I still see some "Unable to delete" messages during runtime while attempting to force compaction on a loaded system but those are also reduced and I'll track them down in a separate effort. I chose to go with refcounting rather than simply changing the ordering in CompactionTask as we need some codification of the ordering relationship between scanners and sstables in order to prevent this type of "error" in the future. The SSTableScanner relies on internal data structures within the SSTR and, while the previous code will hold the reference open and prevent GC due to the pointer it has internally as well as the ifile and dfile references, our previous logical structure of there being no relationship between SSTableScanners being open and SSTR deletion was misleading. While we replicate some of the references in the scanner so the SSTR can technically be deleted out of order and we rely on the filesystem to keep the file open if we have a handle to it, a more clear relationship between the components is preferable IMO. Jonathan Ellis : I threw you on this as reviewer when I was leaning towards log suppression route as it was a trivial effort; Marcus Eriksson : would you be willing to review this as you've been in the compaction and SSTableRewriter space recently? Edit: I should note: While this is a symptom that we see on Windows on the 2.1 branch specifically, this isn't so much a Windows issue as resource ordering issue centered around the compaction process and SSTableScanners.
          Hide
          krummas Marcus Eriksson added a comment -
          Show
          krummas Marcus Eriksson added a comment - Joshua McKenzie sure!
          Hide
          krummas Marcus Eriksson added a comment -

          +1 on v3, totally agree it makes the most sense in this case

          Show
          krummas Marcus Eriksson added a comment - +1 on v3, totally agree it makes the most sense in this case
          Hide
          JoshuaMcKenzie Joshua McKenzie added a comment -

          Committed.

          Show
          JoshuaMcKenzie Joshua McKenzie added a comment - Committed.

            People

            • Assignee:
              JoshuaMcKenzie Joshua McKenzie
              Reporter:
              philipthompson Philip Thompson
              Reviewer:
              Marcus Eriksson
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development