Garbage Collector removed referenced files

[matthpeterson]

A significant number of Imported files were garbage collected despite the presence of "file" entries referencing them. This impacted only the file references within one accumulo.metadata tablet which supported many tablets for a table.

The tablet server hosting the accumulo.metadata tablet died, the tablet was reassigned, and the WALs were recovered. See the logs summary below.

16:04:50 - tserver imports one of the files that will later go missing
17:28:59 - GC recognizes candidate file is in use
17:41:25 - GC gc.SimpleGarbageCollector collect cycle statistics reported
17:42:40 - GC gc.GarbageCollectWriteAheadLogs reports statistics
17:44:49 - GC Thread gc stuck on IO to accumulo master for at least 2 minutes
17:46:26 - GC Thread gc no longer stuck
17:56:06 - datanode dies on tserver hosting accumulo.metadata
...
Tserver reports many errors related to HDFS access, including WAL delete failures
...
17:57:14 - datanode startup
17:57:44 - tserver dies

17:58:45 - master.Master reports tablet assigned to dead tserver
17:58:49 - master.Master reports old location state
17:59:20 - master.Master reports old location state
17:59:20 - master.Master reports assigning tablet
17:59:27 - master.Master reports new location state
17:59:28 - master.Master reports new location state
17:59:29 - master.Master reports new location state
17:59:26 - tserver: Loading accumulo.metadata tablet
17:59:31 - tserver: got assignment from master for tablet, loading and verifying extent
17:59:32 - Starting WAL recovery occurs accumulo.metadata tablet
17:59:32 - WAL recovery complete for accumulo.metadata tablet
17:59:34 - master.EventCoordinator reports accumulo.metadata tablet loaded

18:06:09 - GC deletes file that was previously recognized as in use

18:10:29 - gc.SimpleGarbageCollector collect cycle statistics reported
18:12:00 - Errors begin for one of the missing files

This impacted a 1.8.1 fork that contained the 1.9.1 dataloss bug fixes.

[ctubbsii]

It's possible these were caused by reintroduction of deleted data bugs that were fixed in 1.9.2. It's also possible there's some problem with the metadata scanner used to read the tablet information.

[cshannon]

Closing out as no activity in over 4 years, it can be reopened if this is still a problem.

[cshannon]

I am re-opening this as the problem here may still be happening and needs to be investigated. There are some related/duplicate issues for this as well: #1916, #2322, #2792, and #2293

[cshannon]

I investigated this again yesterday and there are still some reports of this same behavior happening against 1.10.x. It's similar behavior where there is missing data returned from the scan of the accumulo.metdata table during GC leading to references being missed. In this case an entire tablet worth of data is missing which leads to files being deleted that shouldn't because the file references aren't seen.

A simple example of the scenario seen is:

1. accumulo.root has 1 tablet containing the metadata for 4 accumulo.metadata tablets.
2. The 3rd accumulo metadata tablet contains metadata for the 10th, 11th, and 12th tablets in table X.
3. GC runs and all of the metadata contained in the 1st, 2nd, and 4th accumulo.metadata tablets is returned and used appropriately by the garbage collector
4. However, during the GC run all of the data for the 3rd accumulo metadata tablet goes missing which leads to missing the references to files in the 10th, 11th, and 12th tablets from table X.
5. Because the file references are missing, files for the 10th, 11th, 12th tablets of table X get removed

In some instances the issue could be traced to a hardware failure (disk issue) but this has not always been the case. Even if there is a hardware failure the fact that data is missing should be detected during the safety checks of the scan for file references of the metadata table. If there are errors/inconsistencies detected during the scan (due to splits, etc) then the iterator that is used should reset itself to prevent an issue.

However, because there ends up being file references missing and bypassing the checks this would seem to maybe indicate an issue in the iterator error handling/detection so maybe something isn't quite right because GC continued with data not being detected as missing. The iterator used for scanning for file references is the TabletIterator used in version 1.10. It's not known if the issue still exists in 2.1 as there were changes made and a different Iterator is now used but if it does it would likely be in the equivalent iterator used for the references scan in the LinkingIterator in 2.1 .

The root cause of the issue isn't known so it makes it hard to fix or find a solution for now but I talked to @dlmarion about this and thought of a few things to bring up and discuss.

1. Does it make sense to just abort the GC run vs trying to reset the iterator if an error is detected? The gc process runs in a loop anyways and will just re-run the next iteration. It's possible there's an issue with resetting the iterator so maybe just aborting would be better.
2. Is it possible there is actually a server side error that isn't bubbling back to the client which would lead to the client continuing the scan when it shouldn't?
3. Should we try and run an extra sanity check somehow to verify the data is actually correct? For example, should we try also using the Offline iterator to scan and compare? Can we verify we actually received all the tablets we should by checking before and after the run? Do we run the scan multiple times and compare? If we ran multiple times we could take a superset of files seen (anything that truly should be GC'd would just get removed next run)
4. Because an entire tablet of data was missing in this scenario is it possible it's related to the tablet splitting and the data was missed?
5. Does this error actually happen in other cases (scans of other/normal tables) but no one notices usually because missing data during the scan may not be noticed but in this case it is noticed because it leads to errors later? Or is this only related to the metadata table and these specific iterators?

Obviously some more investigating work needs to be done but this is where things currently stand after I started looking into it.

[dlmarion]

Another thought is that LinkingIterator.goodTransition defaults to returning true and only returning false under certain conditions. I'm wondering if that should be reversed, default to returning false and returning true under successful conditions. I'm wondering if there is a new condition that exists that is not being checked and so it returns true currently.

[cshannon]

That is an interesting idea for the logic for the goodTransition method, later this week I can look into that more and test reversing it and see what happens.

I ran some tests yesterday and today trying to break things and so far the iterator has detected all the errors and reset properly. I ran tests with rapid GC happening in a loop concurrently while the metadata table was being split frequently (due to it being configured to a very small size) and also with in memory caching turned off. This produced a lot of messages in the logs where the iterator detected problems do to the splits, etc but it always reset itself properly. Each time the correct rfiles were GC'd and nothing that was removed that shouldn't.

I also looked at exception handling and bubbling up from a server side iterator to the client and that appears to work. There's actually an integration test for this ServerSideErrorIT

I'll continue looking at this more next week. My goal is to try and find a flaw somewhere with a test case because if we can reproduce an error with testing this will be a lot easier to track down.

[cshannon]

I did some more testing this past Friday/Saturday on this and couldn't get an errors to show up still. I did however see in the logs the iterator actually detect inconsistencies in the meatadata table and it fixed itself (just like I said in my previous comment). I talked to @keith-turner about this a bit and he suggested I try testing against 1.10 (and not just 2.1 and main). I also realized I was mostly testing using the mini accumulo cluster which does not use HDFS. So today I spent some time-rerunning my tests against 1.10 and using Uno (so it's a real cluster with HDFS) and I still didn't get an errors and everything worked as it should.

One idea I had that could possibly help the problem would be to require garbage collection to run more than one time and compare results before actually removing files. For example, GC could run the scan to get the file candidates with references multiple times in the same GC run and then compare results and take a superset or fail if inconsistent. Another option is to require more than one GC run before actually deleting. Something like when GC runs and comes comes up with the files it is about to delete maybe we just mark them (in metadata probably) as deleted/to be deleted and a subsequent run could do the actual delete if it detects the file as marked in a previous run so we know we at least had multiple runs where we think we should delete. We could even make it configurable to require X number of positive hits to do a deletion or have a time delay etc.

Running the scan more than once to detect the file references would only actually help if the problem was transient and non-deterministic and was isolated to a single scan and wouldn't just happen in a future scan which is hard to say because we don't know the actual problem. There's also a bit of a chicken/egg problem where if we are writing the GC result back to metadata but metadata scans are the issue and inconsistent it could be a problem. Also this behavior to delay deletion can sort of already be accomplished by using HDFS trash and files can be recovered from there and there is already #3140 to help make the HDFS trash option better but having it built in to GC could also be nice if it would help prevent early deletion in the first place.

[ctubbsii]

There's also a bit of a chicken/egg problem where if we are writing the GC result back to metadata but metadata scans are the issue and inconsistent it could be a problem.

No. The deletion candidates are in a completely separate section of the table than the metadata tablets that could contain existing references. If some issue prevents the file from being seen as a candidate, then it doesn't matter... it won't be deleted. This only is a problem if the file is detected as a candidate, but the checking for existing references among the tablet metadata returns successfully with no reference detected.

[ctubbsii]

Some insight into this issue was recently discovered. It seems that under some extremely rare circumstances (that may be related to hardware failures and HDFS handling of it), the reading of one locality group, where file entries exist, fails, but reading the prev row, which is used for validating the metadata was fully traversed, succeeds. This results in missing some file entries that are still in use. Eventually, the scan comes back normal, but until then, the gc can delete the candidate it believes is not in use.

Several issues were created to try to detect or mitigate this:

• Delete referenced candidates in AccumuloGC #3693 can help by removing candidates that still have references, so they aren't so aggressively checked (it can also help with performance).
• Handle erroneously empty rfile block reads #3694 is the core issue that could help fix this bug. Add unit test for erroneous empty rfile #3695 is a sub-task of that one.
• Add metadata table validation to AccumuloGC #3696 is for adding checks in the GC to attempt to verify the metadata is fully retrieved.
• Add RFile block info to validate the block was read correctly #3698 is for adding internal integrity checks to the RFile file format.
• Consider adding integrity checks into the metadata table's tablet schema #3699 adds general integrity checks for the metadata in the schema.