#113 Weeder should access cache via network
The weeder directly accesses some of the cache's stored
data via the filesystem. A new user recently ran into
a confusing case of cache corruption which turned out
to be caused by a weeder communicating with one cache
via the network and seeing a different cache via the
filesystem. Specifically, at least one thing which
went wrong was that the weeder gave an incorrect
(probably empty) set of MultiPKFile prefixes to the
cache server because it didn't see the graph log
entries for the cache indecies it was deleting. This
resulted in the cache dying with the message "INTERNAL
ERROR: hit on unused CI".
In this case, it wasn't even the user's direct action
which triggered the incorrect weeder run. They had
installed the vesta-server RPM on a host which they
then later decided to make into a client of a different
server. They neither un-installed vesta-server nor
changed /var/lib/vesta to an NFS mount from the other
host. The vesta-server package installs a cron job
which runs the weeder automatically
(/etc/cron.weekly/vestaweed) and this is what ran the
weeder.
While this should never happen in a properly configured
setup, this does demonstrate a new way that an
inexperienced user can shoot themselves in the foot.
It would be best to eliminate it. This means adding
the following to the cache server's network protocol:
- Reading the graph log. (Currently the weeder reads
this directly from the filesystem.)
- Writing a checkpoint of the graph log. (Currently
the weeder directly writes a checkpoint to a temporary
file and passes that filename to the cache's
CommitChkpt function.)
- Storing and retrieving the weeder's stable variables.
(Currently the weeder reads and writes these itself.
By convention they get stored in
/var/lib/vesta/cache/weeder.)
The weeder also uses files to hold graph log entries
during its mark/sweep processing (named in the config
file settings [Weeder]PendingGL and [Weeder]WorkingGL).
These should remain filesystem operations performed
locally. We should probably move these files out of
the weeder's data directory
(/var/lib/vesta/cache/weeder) to some local temporary
directory (/tmp or /var/tmp).
Logged In: YES
user_id=304837
When I first entered this issue, I perhaps somewhat
cavalierly placed it in "feature requests", chalking it up
to a mis-configuration by a new user. I'm changing it now
to a bug.
I've just been investigating a subtle cache corruption
caused by a very similar error (running the weeder on a
machine where the cache is inaccessible via the filesystem).
In this case several things were different:
- Rather than having a different cache in the same
directory, the cache directory ([CacheServer]MetaDataRoot)
did not even exist on the other machine
- Rather than being triggered by a cron job, the weeder run
on the machine where the cache was inaccessible was invoked
manually
- There was a previous partially completed weeder run which
had called EndMark but had failed before checkpointing the
graph log
The symptom, which did not show up until several days after
the problem was caused, was this message from the weeder:
13:04:46.088 04/03/2006 -- Fatal error:
Cache inconsistency detected: non-leased marked CI(s)
with no GL entry!
cis missing GL entries =
6341, 6354
(2 total)
Running Verify_Cache showed that there were quite a few more
cache indecies missing their graph log entries (290 in
total).
The sequence of events which caused the problem was as
follows:
- The first weeder run started and made it past the call to
EndMark but died before checkpointing the graph log.
- This would have created 2.ckp in the graph log
(StartMark returned newLogVer = 2 and EndMark returned
chkptVer = 2).
- In the background, the cache server processed the
deletions sent to it by the weeder with the EndMark call.
This made the weeded CIs available for re-allocation.
- Several hours later, the weeder was started on the other
machine where the cache was inaccessible in the filesystem.
- In trying to determine whether it needed to finish a
previous failed weed, it attempted to load the stable
"weeded" set. It caught the exception FS::DoesNotExist
(because it is stored in the cache's directory which was
not present), which the weeder treats as though the weeded
set is empty (which means that no recovery from a previous
weed was needed).
- The weeder also called the cache's WeederRecovering
method, but since the first weeder process was no longer
running it indicated that the new weeder could proceed.
- At this point, the weeder considered itself to be
starting a new run and called the cache's StartMark
procedure. This caused the cache to stop writing graph
log entries to 2.log and start writing graph log entries
to 3.log (StartMark returned newLogVer = 3).
- The weeder failed when trying to open the pending graph
log (to copy entries from the graph log to the pending
graph log for the mark phase). This was a fatal error
which caused the weeder to exit.
- Immediately after this, the weeder was started on the
correct host (where the cache server was running).
- It recovered the weeded set and other stable weeder
state from the first weeder run.
- It called the cache's EndMark procedure, passing the
same weeded set as before. At this point the cache had an
empty hit filer because the deletions from the first
weeder run had been completed and the second weeder run
had never reached the point of setting a hit filter. As a
result, the cache ignored the CIs sent by the weeder.
However, the call to EndMark did return chkptVer = 3,
indicating that the weeder should write 3.ckp in the graph
log.
- The weeder proceeded to checkpoint the graph log. It
used the set of weeded CIs from the first run, which were
gathered before 2.log was started, yet it was writing
3.ckp (shadowing everything in 2.log). This caused some
graph log entries in 2.log for CIs which had been
re-allocated after the cache server processed deletions
from the first run to be silently discarded.
- Days later when the weeder was next run, two of the CIs
which had lost their graph log entries (because they had
been in 2.log in the graph log) were marked to be kept
during weeding. The weeder noted this inconsistency and
failed with the message above.
First of all, this has made it clear to me that the cache
server should be writing the graph log checkpoint, not the
weeder. The implementation in this area has always been
rather ugly, but this problem is just the latest of a
history of subtle bugs around graph log checkpointing. I'm
certain that at least a few previous bugs could also have
been avoided if the cache server had been made responsible
for checkpointing the graph log earlier. This is roughly
how I see this working:
- The arguments to EndMark will include the graph log roots
to keep, and will not include the MultiPKFile prefixes to
re-write during deletions.
- The first thing the cache will do when processing
deletions will be to write the new graph log checkpoint. As
it does this, it will gather the MultiPKFile prefixes to
re-write during deletions. It will not commit this
checkpoint until later in the process.
- Next, the MultiPKFiles will be re-written, deleting the
weeded cache entire, in the same way as they are currently.
- After the MultiPKFiles have all been re-written, then the
graph log checkpoint will be committed.
- Finally, the wedded CIs will be made available for
re-allocation.
I suppose an alternative would be to only make deleted CIs
available for re-allocation after the weeder calls
CommitChkpt, but that's not my first choice.
Secondly, there are a few other little bugs illustrated by
this chain of events:
- When the weeder finds that the weeded set doesn't exist on
disk, it doesn't check whether the weeder data directory
exists. It could be made to do perform this check, but I
think a better solution is what I proposed in the initial
text of this entry: having the cache server store the
variables on behalf of the weeder rather than having the
weeder read and write files for them.
- The weeder's miscellaneous variables should include the
new log version returned by StartMark. This should be
passed as an argument to EndMark, and if it doesn't match
the current graph log version it should be an error which
stops weeding and prevents the cache from processing
deletions.
- There's actually a serious problem in this area with
weeder recovery: the weeder needs the value returned by
StartMark for finding the PK prefixes of all entries to be
deleted (as it tells the weeder which portion of the graph
log to scan), but in the recovery case the "newLogVer"
member variable of the Weeder class will actually be
uninitialized (until EndMark is called).
- The cache should check that the CIs passed to EndMark (the
ones to be deleted) are a subset of the current hit filter
(set earlier by the weeder's call to SetHitFilter) and that
none of them are leased. It currently checks the first
property with an assertion, but it doesn't check the second.
Rather than an assertion, it should return an error to the
weeder.
Logged In: YES
user_id=304837
Originator: YES
In the bug I just opened against the repository ("ShortIdStock::stockboy: Assertion `leaseValid' failed"), I mentioned the weeder dying with an assertion failure. This happened while it was checkpointing the graph log (between the EndMark and CommitChkpt calls). This seems to have triggered a similar situation to what I described in my last update to this bug. Unlike the cause we saw last time (an administrator mistakenly running the weeder by hand on a host where the cache data was inaccessible), this occurrence was entirely driven by automated cron jobs invoking the weeder on the correct machine. When the weeder was started after this failure, it resumed the weeding process and proceeded to write 113.ckp when it should have been writing 112.ckp. This is a stronger argument in favor of fixing this set of problems sooner.
I added a sanity check (comparing the number of the last
.log file read from the graph log with the new log version
returned by StartMark) which should avoid the problem most
of the time in:
/vesta/vestasys.org/vesta/weeder/18