ValueError (need more than 8 values to unpack) during mutable MDMF repair #1669
Labels
No Label
0.2.0
0.3.0
0.4.0
0.5.0
0.5.1
0.6.0
0.6.1
0.7.0
0.8.0
0.9.0
1.0.0
1.1.0
1.10.0
1.10.1
1.10.2
1.10a2
1.11.0
1.12.0
1.12.1
1.13.0
1.14.0
1.15.0
1.15.1
1.2.0
1.3.0
1.4.1
1.5.0
1.6.0
1.6.1
1.7.0
1.7.1
1.7β
1.8.0
1.8.1
1.8.2
1.8.3
1.8β
1.9.0
1.9.0-s3branch
1.9.0a1
1.9.0a2
1.9.0b1
1.9.1
1.9.2
1.9.2a1
LeastAuthority.com automation
blocker
cannot reproduce
cloud-branch
code
code-dirnodes
code-encoding
code-frontend
code-frontend-cli
code-frontend-ftp-sftp
code-frontend-magic-folder
code-frontend-web
code-mutable
code-network
code-nodeadmin
code-peerselection
code-storage
contrib
critical
defect
dev-infrastructure
documentation
duplicate
enhancement
fixed
invalid
major
minor
n/a
normal
operational
packaging
somebody else's problem
supercritical
task
trivial
unknown
was already fixed
website
wontfix
worksforme
No Milestone
No Assignees
2 Participants
Notifications
Due Date
No due date set.
Reference: tahoe-lafs/trac-2024-07-25#1669
Loading…
Reference in New Issue
Block a user
No description provided.
Delete Branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Gateway is running Mac OS X, mutable.format=mdmf
Sometimes running deep check from WUI results in
this check is that happened after https://tahoe-lafs.org/trac/tahoe-lafs/ticket/1670
Attachment incident-2012-02-10--07-10-36Z-yyfpk7a.flog.bz2 (42352 bytes) added
possible related incident file
Attachment incident-2012-02-10--07-11-26Z-qwg5ivy.flog.bz2 (42111 bytes) added
possible related incident file #3
Attachment incident-2012-02-10--07-14-46Z-fpevtli.flog.bz2 (42576 bytes) added
possible related incident file 4
added possible related incident files
Addition:
same from console,
reproducible.
even if gateway is not doing anything.
no incident file this time(none was generated)
last (possible relevant) lines of twisted.log
attempt to perform same repair operation on Windows or Linux nodes in same grid results in basically same issue.
#1672 was marked as a duplicate of this.
Note that although mutable.format is mdmf, we don't have enough evidence to conclude that this is specific to MDMF. It seems likely that it is a regression in the 1.9.x mutable publisher/repairer, though.
Crashes while repair on Mac OS Xto ValueError (need more than 8 values to unpack) during mutable MDMF repairthis was planned to be added to #1672
davidsarah,
mutable.format is not set
but directory was created as mutable in WUI(becouse I have other problems with concurrent access otherwise, mutable dirs at least work and manual deep-checks of subdirs - shows all is fine)
also,
this one is from linux
CentOS5.4
is exact python versions be of interest?
The "exceptions.RuntimeError: Request.finish called on a request after its connection was lost; use Request.notifyFinish to keep track of this." is probably a duplicate of #1664; I don't see any strong evidence that it's related to the ValueError.
Investigating.
Update: I hate it when I post partial results of my investigations and then someone (usually Brian) goes and finishes debugging it and fixing it before I do. But, I figure that's not a good reason to withhold information, so here's my partial results.
• The stack trace in the original post shows a tuple with 8 elements being returned in place of "verinfo", but "verinfos" are supposed to have 9 elements.
• The elements shown in the stack trace in the original post are not the elements of a verinfo. A verinfo is (according to [mutable/layout.py]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L433) is (int -- seqnum, cryptoval -- hash, cryptoval -- salt or hash, int -- segsize, int -- datalen, int -- k, int -- n, str -- prefix for signing, tuple -- offsets). The stack trace in the original post shows something that is (int -- seqnum, cryptoval -- hash?, int -- k, int -- n, int -- segsize, int -- datalen, str -- prefix for signing?, tuple -- offsets).
• The docstring of [SDMFSlotWriteProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L433 is wrong about the 2-indexed item -- it is a hash or a salt, not "a blank (nothing)"
• [SDMFSlotWriteProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L433 and [MDMFSlotReadProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L1692 return the same shape of tuple, but [MDMFSlotWriteProxy.get_verinfo]source:git/src/allmydata/mutable/layout.py?annotate=blame&rev=87ca4fc7055faaea7e54cbab4584132b021e42e1#L1102 returns a different shape. Aha! And the latter matches the data shown in the stack trace in the original post, so it is one of those that is ending up getting parsed as a "verinfo" and causing this exception.
• I wrote a type-checking function that asserts the shape of a verinfo tuple and sprinkled it everywhere and ran unit tests and got unit tests failures.
• I don't know how this code that says "d2 = reader.get_verinfo(); d2.addErrback(…)" in [mutable/servermap.py]source:git/src/allmydata/mutable/servermap.py?annotate=blame&rev=470acbf1e1d0a525cb8af9fb7a82ebe09033e8ca#L705 ever worked! None of the functions named "get_verinfo" that I see return a Deferred. But, if that function raises an AttributeError every time (saying "tuple has no such attribute 'addErrback'"), wouldn't we have noticed before now? That line of code was added in changeset:bb10d685ed86eb08 11 months ago and has been in 1.9.x all along. Hm... but I see that any AttributeError raised from there would get handled by [_query_failed]source:git/src/allmydata/mutable/servermap.py?annotate=blame&rev=470acbf1e1d0a525cb8af9fb7a82ebe09033e8ca#L981...
Okay, I'm taking a brief break. but DON'T GO AND FIX THIS WITHOUT ME AND HAVE ALL THE FUN.
Okay since I wrote comment:87338 I patched pristine 1.9.1 to raise an instance of a newly defined exception class instead of to execute
d2.addErrback. I expected that this would not change unit test behavior since I believed thatd2.addErrbackwould never do anything but raise an exception (AttributeError). However, instead I got a lot of test failures/errors.So I commented out the "raise exception" and wrote a
log.msg(…)debugprint. That shows thatd2is in fact a Deferred. I don't see how:Oh, okay, I see that !MDMFSlotReadProxy does return a deferred tuple, where the other two implementations of
get_verinfoin mutable/layout.py return an immediate tuple... I guess that one is the only one that is getting invoked in that_got_results? ...Also, I'll attach the patch that adds type-checking.
So, basically I'm pretty sure I see at least one or two serious bugs. 1. different shape of tuple passed around as a "verinfo" from !MDMFSlotWriteProxy than from !SDMFSlotWriteProxy or !MDMFSlotReadProxy, and 2.
d2 = reader.get_verinfo(); d2.addErrback(…). However, I don't understand how the latter isn't already showing up as unit test failures and common failures of mutable file operations. And, I don't understand the full scope of these two -- under what conditions they strike and what their consequences are.Unsetting my ownership of this ticket since I'm going to bed and I no longer mind if you snatch it out from under me. :-)
Attachment 1.9.1-debugging-ticket1669.diff.txt (6967 bytes) added
Taking this ticket back...
Here's a patch against 1.9.2 which I don't intend to commit for the actual 1.9.2 release. Probably we could use this patch to finish understanding the scope of the bug, commit some variant of this patch to trunk (I like Brian's suggestion to replace the verinfo tuple with an object), and then commit some subset or minimized variant of this patch to 1.9.2.
Also, there's one test failure that I don't understand.
Attachment patch1.diff.txt (41188 bytes) added
Update: I think that the only place the 8-tuple "verinfo" could get generated and passed around is [here]source:1.9.2/src/allmydata/mutable/servermap.py?rev=5482#L740. However, tracing backwards to see what could have led to that line of code, the only thing that can lead to that code is someone updating an MDMF by changing only part of it, and the only time that is ever done is if someone uses [the WAPI]source:1.9.2/docs/frontends/webapi.rst?rev=5469#writing-uploading-a-file to do so. I doubt that anything vikarti did, and certainly not a deep-check, was doing that, which leads me to think that the 8-tuple "verinfo" must have gotten generated and passed around in some other way.
Aha! Then it must be the one other possibility -- [here]source:1.9.2/src/allmydata/mutable/publish.py?rev=5481#L883. That is called from exactly one place -- [here]source:1.9.2/src/allmydata/mutable/publish.py?rev=5481#L856. Which is called from exactly one place -- [here]source:1.9.2/src/allmydata/mutable/publish.py?rev=5481#L764. Which is called from exactly one place -- [here]source:1.9.2/src/allmydata/mutable/publish.py?rev=5481#L616. Which means that it is when a
Publishobject publishes the file's contents...Investigating a bit more...
Okay, I think I've finally figured out why this doesn't happen in the unit tests. There are no unit tests of mutable file repair that involve actually repairing damage!
test_repairer is all immutable
The one occurrence of "check_and_repair" in test_mutable says this:
So it doesn't actually repair, just check, since it is a readcap.
All the occurrences of check_and_repair in test_deepcheck appear to be running on perfectly healthy files, so now repairs are performed.
Here is a patch which adds debugprintouts showing the trail of the problem. In practice, e.g. in vikarti's original post to this ticket, I believe that "xxx 1", then "xxx 2", then "xxx 3" will be encountered, leading to an exception. However when running the unit tests with this patch in place, you'll see xxx 1 and 2 but never "xxx 3", because there is no test of repair-which-actually-fixes-damage.
So I currently believe that vikarti's bug will happen every single time you have an MDMF with damage and you repair it. Next step: to write a unit test that tests that belief! But first, sleep.
Unsetting my ownership of this ticket in order to signal that I would be okay with (indeed, quite grateful for) someone else working on it while I sleep.
Here's the minimal patch that probably fixes the bug. Please don't ship this in a new stable release until we have a unit test of it!
Attaching a patch which is intended to eventually be submitted for trunk (i.e., for Tahoe-LAFS v1.10) but not for 1.9.2. It is basically "a bunch of small cleanups" around mutable files. Needs work. I think it causes one unit test to fail. There are several things I want to talk to Kevan about, most of which are currently indicated in this patch with the addition of a comment that says something "XXX Why such and such?".
Brian: your idea of replace verinfo tuple with an object is a good one, and I would be happy if you would do it, but I would prefer it if you would base that on top of this patch.
Attachment diff.txt (40600 bytes) added
Ah, I was wrong to say that there are no tests. There is [test_mdmf_repairable_5shares]source:1.9.2/src/allmydata/test/test_mutable.py?rev=5479#L2050. Now why doesn't this test exercise the bug...
Aha. I turned on code coverage display (see wiki/HowToWriteTests) and ran [test_mdmf_repairable_5shares]source:1.9.2/src/allmydata/test/test_mutable.py?rev=5479#L2050. This immediately shows that the code in question never gets exercised by that test. Aha! Because that test invokes
checkand then invokesrepair. The code in question is in the implementation ofcheck_and_repair.There, I made a new test that invokes
check_and_repairand it exercises the bug. Victory!Hm, I can't attach files of this size to this ticket (due to #1581). Fortunately, I can use tahoe-lafs instead!
(@@https://lafsgateway.zooko.com/file/URI:CHK:bbrr25dwjjmirkmhefxfaepj5y:4p56766gfzu4pztkya3rpo3sok5bffyggrp3u7ody5nnwjipntfa:1:1:102848/@@named=/fix.dpatch.txt@@)
Review needed!
I'd like there to be less duplicated code in the check/repair tests, but that can wait until 1.10. Continuing review...
In changeset:8c6c410b87ebeea1:
Also changeset:adca74d9f8a07d18, which did not get auto-commented for some reason: "Tests for ref #1669. Also refactor the existing tests to reduce duplicated code and to fix a cut-and-paste error that caused one case (successful SDMF repair) to go untested."
In changeset:8c6c410b87ebeea1:
In changeset:5524/1.9.2:
Also [5523/1.9.2] "Tests for ref #1669. Also refactor the existing tests to reduce duplicated code and to fix a cut-and-paste error that caused one case (successful SDMF repair) to go untested."
In changeset:5878/cloud-backend: