Opened at 2015-08-14T21:17:49Z
Closed at 2015-08-25T17:42:19Z
#2482 closed defect (invalid)
backup stopped with "UnrecoverableFileError:"
Reported by: | zooko | Owned by: | |
---|---|---|---|
Priority: | normal | Milestone: | undecided |
Component: | code | Version: | 1.10.1 |
Keywords: | backup | Cc: | |
Launchpad Bug: |
Description
The tail end of the output from time tahoe backup -v -v -v . papers: is:
skipping '/papers/incoming-on-sparkn/what-must-i-do-to-get-well-by-elma-stuart.pdf'.. skipping '/papers/incoming-on-sparkn/sullivan2015(1).pdf'.. skipping '/papers/incoming-on-sparkn/cai2015.pdf'.. skipping '/papers/incoming-on-sparkn/10.1038@nn.3922.pdf'.. uploading '/papers/incoming-on-sparkn/JCI6223(1).pdf'.. /papers/incoming-on-sparkn/JCI6223(1).pdf -> URI:CHK:phankodobfvdzqb22x52gqrbpe:2no43tgyrd2jbtnq33axkhe6mosj5bpno6cyqf4ivhmgzbule7kq:1:1:312823 uploading '/papers/incoming-on-sparkn/Onodera-2014-“Increased sugar uptake promotes oncogenesis via EPAC⁄RAP1 and O-GlcNAc pathways”.pdf'.. /papers/incoming-on-sparkn/Onodera-2014-“Increased sugar uptake promotes oncogenesis via EPAC⁄RAP1 and O-GlcNAc pathways”.pdf -> URI:CHK:gkqgvv4wvjkasviugffnwjcik4:yi4midal3fap7mlquk2vuntxjmqwyloeprspdbgyrz5eic7smsza:1:1:6531824 uploading '/papers/incoming-on-sparkn/Reaven-2003-“Insulin Resistance and Compensatory Hyperinsulinemia — The Key Player Between Cigarette Smoking and Cardiovascular Disease?”.pdf'.. /papers/incoming-on-sparkn/Reaven-2003-“Insulin Resistance and Compensatory Hyperinsulinemia — The Key Player Between Cigarette Smoking and Cardiovascular Disease?”.pdf -> URI:CHK:qid72hqugoeuzbt3hk2m5kdseu:mhvkanviylb3qggewvhlpa6dykxjbwjlocimho7zalkqfzmjfsrq:1:1:60275 uploading '/papers/incoming-on-sparkn/Nebeling-1992-“Effects of dietary-induced ketosis on tumor metabolism, nutritional status, and quality of life in pediatric oncology patients (dissertation)”.pdf'.. /papers/incoming-on-sparkn/Nebeling-1992-“Effects of dietary-induced ketosis on tumor metabolism, nutritional status, and quality of life in pediatric oncology patients (dissertation)”.pdf -> URI:CHK:kltjnhayfnedca57yazlkhpmte:wsovdpmlmjv4wvyw2ttro5c7ptzoxlurz35qaez3vbqlhuwvx4iq:1:1:8519379 uploading '/papers/incoming-on-sparkn/Poff-2014-“Ketone supplementation decreases tumor cell viability and prolongs survival of mice with metastatic cancer”.pdf'.. /papers/incoming-on-sparkn/Poff-2014-“Ketone supplementation decreases tumor cell viability and prolongs survival of mice with metastatic cancer”.pdf -> URI:CHK:pxtlbru3ayigforsgkfn7epigm:zt5vv466ybahzfnmhrnsn6sntnvvltgdlxwu3azdti3qutewv42a:1:1:645271 uploading '/papers/incoming-on-sparkn/Wang-2015-“Hyperbaric oxygen promotes malignant glioma cell growth and inhibits cell apoptosis”.pdf'.. /papers/incoming-on-sparkn/Wang-2015-“Hyperbaric oxygen promotes malignant glioma cell growth and inhibits cell apoptosis”.pdf -> URI:CHK:j7k4uwglqrm7zj3qsu5ujr6bay:svawden2m62l2wtougbv5ati4jj6yermlogsfwnltbaxvcprosqq:1:1:1293042 creating directory for '/papers/incoming-on-sparkn' creating directory for '/papers' Traceback (most recent call last): File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/runner.py", line 160, in run rc = runner(sys.argv[1:], install_node_control=install_node_control) File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/runner.py", line 145, in runner rc = cli.dispatch[command](so) File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/cli.py", line 543, in backup rc = tahoe_backup.backup(options) File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/tahoe_backup.py", line 326, in backup return bu.run() File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/tahoe_backup.py", line 123, in run put_child(archives_url, now, new_backup_dircap) File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/tahoe_backup.py", line 57, in put_child raise HTTPError("Error during put_child", resp) HTTPError: Error during put_child: 410 Gone UnrecoverableFileError: the directory (or mutable file) could not be retrieved, because there were insufficient good shares. This might indicate that no servers were connected, insufficient servers were connected, the URI was corrupt, or that shares have been lost due to server departure, hard drive failure, or disk corruption. You should perform a filecheck on this object to learn more. real 0m47.078s user 0m0.892s sys 0m0.334s
The version of Tahoe-LAFS is:
allmydata-tahoe: 1.10.1 [master: 2875a9ffc415cd665026419001f2311b4efd44e1] foolscap: 0.8.0 pycryptopp: 0.6.0.1206569328141510525648634803928199668821045408958 zfec: 1.4.24 Twisted: 15.0.0 Nevow: 0.11.1 zope.interface: unknown python: 2.7.6 platform: Linux-Ubuntu_14.04-x86_64-64bit_ELF pyOpenSSL: 0.13 OpenSSL: 1.0.1f [6 Jan 2014] simplejson: 3.3.1 pycrypto: 2.6.1 pyasn1: 0.1.7 mock: 1.0.1 service-identity: 14.0.0 characteristic: 14.3.0 pyasn1-modules: 0.0.5 setuptools: 3.3
Attachments (5)
Change History (14)
Changed at 2015-08-14T21:18:41Z by zooko
comment:1 Changed at 2015-08-14T21:20:55Z by zooko
comment:2 Changed at 2015-08-14T21:25:51Z by zooko
I then started a flogtool tail going with this command: tahoe debug flogtool tail --verbose --save-to=flog-tail.flog --timestamps=utc ~/.tahoe/private/logport.furl, and then I re-ran the exact same tahoe backup command, like this: time tahoe backup -v -v -v . papers:. This time the tail of the output of the tahoe backup command was this:
skipping '/papers/incoming-on-sparkn/Morris et al. 2014 - Is Alzheimerʼs Disease a Systemic Disease.pdf'.. skipping '/papers/incoming-on-sparkn/UKPDS - low fat, high fibre doesnʼt work.pdf'.. skipping '/papers/incoming-on-sparkn/Medical Hypotheses Volume 76 issue 2 2011 [doi 10.1016%2Fj.mehy.2010.09.006] Edward Henry Mathews; Leon Liebenberg; Ruaan Pelzer -- High-glycolytic cancers and their interplay with the bodyʼs glucose demand and supply cycl-1.pdf'.. skipping '/papers/incoming-on-sparkn/Medical Hypotheses Volume 76 issue 2 2011 [doi 10.1016%2Fj.mehy.2010.09.006] Edward Henry Mathews; Leon Liebenberg; Ruaan Pelzer -- High-glycolytic cancers and their interplay with the bodyʼs glucose demand and supply cycl.pdf'.. skipping '/papers/incoming-on-sparkn/1993y Riordan Treatment of active Crohnʼs disease by exclusion diet - East Anglian Multicentre Controlled Trial.pdf'.. skipping '/papers/incoming-on-sparkn/Swerdlow - Mitochondrial Manipulation and the Quest for Alzheimerʼs Treatments.pdf'.. skipping '/papers/incoming-on-sparkn/Bredesen-2014-“Reversal of cognitive decline: A novel therapeutic program”.pdf'.. skipping '/papers/incoming-on-sparkn/ioi150059.pdf'.. skipping '/papers/incoming-on-sparkn/Poff-2015-“Non-Toxic Metabolic Management of Metastatic Cancer in VM Mice: Novel Combination of Ketogenic Diet, Ketone Supplementation, and Hyperbaric Oxygen Therapy”.pdf'.. skipping '/papers/incoming-on-sparkn/what-must-i-do-to-get-well-by-elma-stuart.pdf'.. skipping '/papers/incoming-on-sparkn/sullivan2015(1).pdf'.. skipping '/papers/incoming-on-sparkn/cai2015.pdf'.. skipping '/papers/incoming-on-sparkn/10.1038@nn.3922.pdf'.. skipping '/papers/incoming-on-sparkn/JCI6223(1).pdf'.. skipping '/papers/incoming-on-sparkn/Onodera-2014-“Increased sugar uptake promotes oncogenesis via EPAC⁄RAP1 and O-GlcNAc pathways”.pdf'.. skipping '/papers/incoming-on-sparkn/Reaven-2003-“Insulin Resistance and Compensatory Hyperinsulinemia — The Key Player Between Cigarette Smoking and Cardiovascular Disease?”.pdf'.. skipping '/papers/incoming-on-sparkn/Nebeling-1992-“Effects of dietary-induced ketosis on tumor metabolism, nutritional status, and quality of life in pediatric oncology patients (dissertation)”.pdf'.. skipping '/papers/incoming-on-sparkn/Poff-2014-“Ketone supplementation decreases tumor cell viability and prolongs survival of mice with metastatic cancer”.pdf'.. skipping '/papers/incoming-on-sparkn/Wang-2015-“Hyperbaric oxygen promotes malignant glioma cell growth and inhibits cell apoptosis”.pdf'.. re-using old directory for '/papers/incoming-on-sparkn' re-using old directory for '/papers' Traceback (most recent call last): File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/runner.py", line 160, in run rc = runner(sys.argv[1:], install_node_control=install_node_control) File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/runner.py", line 145, in runner rc = cli.dispatch[command](so) File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/cli.py", line 543, in backup rc = tahoe_backup.backup(options) File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/tahoe_backup.py", line 326, in backup return bu.run() File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/tahoe_backup.py", line 123, in run put_child(archives_url, now, new_backup_dircap) File "/usr/local/lib/python2.7/dist-packages/allmydata/scripts/tahoe_backup.py", line 57, in put_child raise HTTPError("Error during put_child", resp) HTTPError: Error during put_child: 410 Gone UnrecoverableFileError: the directory (or mutable file) could not be retrieved, because there were insufficient good shares. This might indicate that no servers were connected, insufficient servers were connected, the URI was corrupt, or that shares have been lost due to server departure, hard drive failure, or disk corruption. You should perform a filecheck on this object to learn more. real 0m1.996s user 0m1.378s sys 0m0.275s
And the resulting flog tail file (which I will attach to this ticket), dumps to this:
Application versions (embedded in logfile): Nevow: 0.11.1 OpenSSL: 1.0.1f Twisted: 15.0.0 allmydata-tahoe: 1.10.1 characteristic: 14.3.0 foolscap: 0.8.0 mock: 1.0.1 platform: Linux-Ubuntu_14.04-x86_64-64bit_ELF pyOpenSSL: 0.13 pyasn1: 0.1.7 pyasn1-modules: 0.0.5 pycrypto: 2.6.1 pycryptopp: 0.6.0.1206569328141510525648634803928199668821045408958 python: 2.7.6 service-identity: 14.0.0 setuptools: 3.3 simplejson: 3.3.1 twisted: 15.0.0 zfec: 1.4.24 zope.interface: unknown PID: 18820 gzi2nwh4#1903 2015-08-14_21:24:28.339945Z: SharemapUpdater(ia2sk): starting (MODE_READ) gzi2nwh4#1904 2015-08-14_21:24:28.340042Z: sending query to [6dwd2q], readsize=4000 gzi2nwh4#1905 2015-08-14_21:24:28.505961Z: got result from [6dwd2q], 0 shares gzi2nwh4#1906 2015-08-14_21:24:28.506059Z: _check_for_done, mode is 'MODE_READ', 0 queries outstanding, 0 extra servers available, 0 'must query' servers left, need_privkey=False gzi2nwh4#1907 2015-08-14_21:24:28.506081Z: all queries are retired, no extra servers: done gzi2nwh4#1908 2015-08-14_21:24:28.506105Z: servermap: gzi2nwh4#1909 2015-08-14_21:24:28.506130Z: _got_results done gzi2nwh4#1910 2015-08-14_21:24:28.506159Z: _check_for_done, mode is 'MODE_READ', 0 queries outstanding, 0 extra servers available, 0 'must query' servers left, need_privkey=False gzi2nwh4#1911 2015-08-14_21:24:28.506174Z: but we're not running gzi2nwh4#1912 2015-08-14_21:24:28.516350Z: web: 127.0.0.1 GET /uri/[CENSORED]..?t=json 410 390 gzi2nwh4#1913 2015-08-14_21:24:29.706012Z: SharemapUpdater(ia2sk): starting (MODE_READ) gzi2nwh4#1914 2015-08-14_21:24:29.706408Z: sending query to [6dwd2q], readsize=4000 gzi2nwh4#1915 2015-08-14_21:24:29.819582Z: got result from [6dwd2q], 0 shares gzi2nwh4#1916 2015-08-14_21:24:29.819817Z: _check_for_done, mode is 'MODE_READ', 0 queries outstanding, 0 extra servers available, 0 'must query' servers left, need_privkey=False gzi2nwh4#1917 2015-08-14_21:24:29.819844Z: all queries are retired, no extra servers: done gzi2nwh4#1918 2015-08-14_21:24:29.819874Z: servermap: gzi2nwh4#1919 2015-08-14_21:24:29.819904Z: _got_results done gzi2nwh4#1920 2015-08-14_21:24:29.819935Z: _check_for_done, mode is 'MODE_READ', 0 queries outstanding, 0 extra servers available, 0 'must query' servers left, need_privkey=False gzi2nwh4#1921 2015-08-14_21:24:29.819952Z: but we're not running gzi2nwh4#1922 2015-08-14_21:24:29.830873Z: web: 127.0.0.1 PUT /uri/[CENSORED]..?t=uri 410 390
Note, that's the complete output of the dump — only 43 lines.
Changed at 2015-08-14T21:26:19Z by zooko
comment:3 Changed at 2015-08-14T21:28:18Z by zooko
I clicked the "report an incident" button and it generated incident-2015-08-14--21-27-34Z-tvkqqwy.flog.bz2
Changed at 2015-08-14T21:29:07Z by zooko
comment:4 Changed at 2015-08-14T21:55:44Z by zooko
I updated to current git HEAD and re-ran the test and got the same result. tahoe version now says:
allmydata-tahoe: 1.10.1a1.post66.dev0 [master: 7309aed524f3bc44ec4035d35556118eea6416ba-dirty] foolscap: 0.8.0 pycryptopp: 0.6.0.1206569328141510525648634803928199668821045408958 zfec: 1.4.24 Twisted: 15.0.0 Nevow: 0.11.1 zope.interface: unknown python: 2.7.6 platform: Linux-Ubuntu_14.04-x86_64-64bit_ELF pyOpenSSL: 0.13 OpenSSL: 1.0.1f [6 Jan 2014] simplejson: 3.3.1 pycrypto: 2.6.1 pyasn1: 0.1.8 service-identity: 14.0.0 characteristic: 14.3.0 pyasn1-modules: 0.0.5 setuptools: 3.3
comment:5 Changed at 2015-08-14T21:59:43Z by zooko
Then I tried a deep-check. The stdout was:
zooko@spark /papers $ time tahoe deep-check --verbose --verify papers: '<root>': Unhealthy: no versions are recoverable ERROR: UnrecoverableFileError(no recoverable versions) "[Failure instance: Traceback: <class 'allmydata.mutable.common.UnrecoverableFileError'>: no recoverable versions" /usr/local/lib/python2.7/dist-packages/Twisted-15.0.0-py2.7-linux-x86_64.egg/twisted/internet/base.py:824:runUntilCurrent /usr/local/lib/python2.7/dist-packages/foolscap/eventual.py:26:_turn /usr/local/lib/python2.7/dist-packages/Twisted-15.0.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py:383:callback /usr/local/lib/python2.7/dist-packages/Twisted-15.0.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py:491:_startRunCallbacks --- <exception caught here> --- /usr/local/lib/python2.7/dist-packages/Twisted-15.0.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py:578:_runCallbacks /usr/local/lib/python2.7/dist-packages/allmydata_tahoe-1.10.1a1.post66.dev0-py2.7.egg/allmydata/mutable/filenode.py:400:_get_version real 0m0.743s user 0m0.392s sys 0m0.080s
I'll attach the flog tail and the incident report file that I generated by the "report an incident" button.
Changed at 2015-08-14T22:00:10Z by zooko
Changed at 2015-08-14T22:00:29Z by zooko
comment:6 Changed at 2015-08-14T22:02:24Z by zooko
I used tahoe debug dump-cap to get more information about the root directory which is the one that is unrecoverable according to that deep-check output from comment:5:
storage index: ia2sk372zlgrf5o6s3pet44wii fingerprint: xtac4ubcnr5eqo6d7h4wyj5sm522olj4mthizz2i3lfw2b5nla6q
comment:7 Changed at 2015-08-17T14:46:42Z by daira
raise Violation("cannot serialize %s (%s)" % (obj, name)) foolscap.tokens.Violation: Violation (<RootSlicer>.<call-0-1-msg>.<arg[0 ]-of-msg>.??.??): ("cannot serialize The '[drop_upload] local.directory' parameter was '/home/zooko/drop_upload' but there is no directory at that location. (<type 'exceptions.AssertionError'>)",)
Is [drop_upload] enabled set to true in tahoe.cfg? Try setting it to false. (This might be unrelated to the backup error, but I want to eliminate it from consideration if so.)
comment:8 Changed at 2015-08-21T16:19:30Z by zooko
I unset that setting and reproduced the issue — same behavior after drop upload was disabled.
comment:9 Changed at 2015-08-25T17:42:19Z by daira
- Resolution set to invalid
- Status changed from new to closed
This was due to Zooko's TLoS3 subscription having been cancelled.
I just uploaded attachment:flog-catchup.flog, which resulted from using this command: time tahoe debug flogtool tail --verbose --catch-up --save-to=flog-catchup.flog --timestamps=utc ~/.tahoe/private/logport.furl. If you look at that file with flogtool dump --timestamps=utc, it outputs this: