tahoe-lafs/trac-2024-07-25
2
0
Issues 1.1k Wiki Activity

nondeterministic failure of allmydata.test.test_download.DownloadTest.test_lost_servers with NotEnoughSharesError #1197

New issue
Closed
opened 2010-09-11 02:22:08 +00:00 by davidsarah · 6 comments
davidsarah commented 2010-09-11 02:22:08 +00:00
Owner
Copy link

(http://tahoe-lafs.org/buildbot/builders/FreeStorm%20WinXP-x86%20py2.6/builds/273/steps/test/logs/stdio) :

[ERROR]: allmydata.test.test_download.DownloadTest.test_lost_servers

Traceback (most recent call last):
Failure: allmydata.interfaces.NotEnoughSharesError: ran out of
shares: complete=sh4 pending=Share(sh7-on-k6vb2) overdue= unused=
need 3. Last failure: [Failure instance: Traceback (failure with no
frames): <class 'foolscap.tokens.RemoteException'>: <RemoteException
around '[Failure instance: Traceback: <class
'allmydata.test.no_network.IntentionalError'>: I was asked to break
c:\python26\lib\site-packages\twisted\internet\base.py:778:runUntilCurrent
build\bdist.win32\egg\foolscap\eventual.py:26:_turn
c:\python26\lib\site-packages\twisted\internet\defer.py:280:callback
c:\python26\lib\site-packages\twisted\internet\defer.py:354:_startRunCallbacks
--- <exception caught here> ---
c:\python26\lib\site-packages\twisted\internet\defer.py:371:_runCallbacks
c:\buildbot_tahoe\freestorm_winxp-x86_py2.6\build\src\allmydata\test\no_network.py:81:<lambda>
c:\buildbot_tahoe\freestorm_winxp-x86_py2.6\build\src\allmydata\test\no_network.py:68:_call
]'>
]

This test succeeds on other builders, and in the next build of the same source.

(http://tahoe-lafs.org/buildbot/builders/FreeStorm%20WinXP-x86%20py2.6/builds/273/steps/test/logs/stdio) : ``` [ERROR]: allmydata.test.test_download.DownloadTest.test_lost_servers Traceback (most recent call last): Failure: allmydata.interfaces.NotEnoughSharesError: ran out of shares: complete=sh4 pending=Share(sh7-on-k6vb2) overdue= unused= need 3. Last failure: [Failure instance: Traceback (failure with no frames): <class 'foolscap.tokens.RemoteException'>: <RemoteException around '[Failure instance: Traceback: <class 'allmydata.test.no_network.IntentionalError'>: I was asked to break c:\python26\lib\site-packages\twisted\internet\base.py:778:runUntilCurrent build\bdist.win32\egg\foolscap\eventual.py:26:_turn c:\python26\lib\site-packages\twisted\internet\defer.py:280:callback c:\python26\lib\site-packages\twisted\internet\defer.py:354:_startRunCallbacks --- <exception caught here> --- c:\python26\lib\site-packages\twisted\internet\defer.py:371:_runCallbacks c:\buildbot_tahoe\freestorm_winxp-x86_py2.6\build\src\allmydata\test\no_network.py:81:<lambda> c:\buildbot_tahoe\freestorm_winxp-x86_py2.6\build\src\allmydata\test\no_network.py:68:_call ]'> ] ``` This test succeeds on other builders, and in the [next build](http://tahoe-lafs.org/buildbot/builders/FreeStorm%20WinXP-x86%20py2.6/builds/274/steps/test/logs/stdio) of the same source.
tahoe-lafs added the
code-network
major
defect
1.8β
 labels 2010-09-11 02:22:08 +00:00
tahoe-lafs added this to the 1.8.0 milestone 2010-09-11 02:22:08 +00:00
zooko commented 2010-09-11 03:27:35 +00:00
Author
Owner
Copy link

I have seen this a couple of times now. I first saw it after applying changeset:0475bd8e27ae8307. I suspect changeset:0475bd8e27ae8307 causes it. :-(

I have seen this a couple of times now. I first saw it after applying changeset:0475bd8e27ae8307. I suspect changeset:0475bd8e27ae8307 causes it. :-(
zooko commented 2010-09-11 06:18:13 +00:00
Author
Owner
Copy link

Ugh, I spent a few hours just now trying to make allmydata.test.test_download.DownloadTest.test_lost_servers deterministic and was not able to do so. Now that I'm writing this, I think maybe I don't even want allmydata.test.test_download.DownloadTest.test_lost_servers to be deterministic. It is basically a "system test". Maybe it is okay to leave it with some non-determinism (which I assume comes from iterating over a dict or a set of servers) in order to show up issues like this one, as long as also write a deterministic, narrowed test for each such issue that shows up.

Okay I'll try that next...

Ugh, I spent a few hours just now trying to make `allmydata.test.test_download.DownloadTest.test_lost_servers` deterministic and was not able to do so. Now that I'm writing this, I think maybe I don't even *want* `allmydata.test.test_download.DownloadTest.test_lost_servers` to be deterministic. It is basically a "system test". Maybe it is okay to leave it with some non-determinism (which I assume comes from iterating over a dict or a set of servers) in order to show up issues like this one, as long as also write a deterministic, narrowed test for each such issue that shows up. Okay I'll try that next...
zooko commented 2010-09-11 07:19:44 +00:00
Author
Owner
Copy link

Here is the last part of _trial_temp/test.log (created with FLOGFILE=flog.out.bz2 FLOGLEVEL=1 FLOGTOTWISTED=1 PYTHONPATH=src/ trial --rterror allmydata.test.test_download.DownloadTest.test_lost_servers) of a run in which the download succeeded:

2010-09-11 00:00:19-0600 [-] imm Node(54cbd6tx).get_segment(1)
2010-09-11 00:00:19-0600 [-] error requesting 60+24 from 6jdsp for si 54cbd6tx
2010-09-11 00:00:19-0600 [-] abandoning Share(sh0-on-6jdsp)
2010-09-11 00:00:19-0600 [-] error requesting 60+24 from ysbz4 for si 54cbd6tx
2010-09-11 00:00:19-0600 [-] abandoning Share(sh1-on-ysbz4)
2010-09-11 00:00:19-0600 [-] error requesting 60+24 from k6vb2 for si 54cbd6tx
2010-09-11 00:00:19-0600 [-] abandoning Share(sh2-on-k6vb2)
2010-09-11 00:00:19-0600 [-] error requesting 0+1024 from alg6u for si 54cbd6tx
2010-09-11 00:00:19-0600 [-] abandoning Share(sh3-on-alg6u)
2010-09-11 00:00:19-0600 [-] got error from [xgru5adv]
2010-09-11 00:00:19-0600 [-] storage: get_buckets 54cbd6txyhbfqrdoclhpinsux4
2010-09-11 00:00:19-0600 [-] storage: get_buckets 54cbd6txyhbfqrdoclhpinsux4
2010-09-11 00:00:19-0600 [-] got error from [rvsry4kn]
2010-09-11 00:00:19-0600 [-] storage: get_buckets 54cbd6txyhbfqrdoclhpinsux4
2010-09-11 00:00:19-0600 [-] got error from [fob7vqgd]
2010-09-11 00:00:19-0600 [-] delivering segment(1)
2010-09-11 00:00:19-0600 [-] Segmentation got data: want [72-310), given [72-144), for segnum=1
2010-09-11 00:00:19-0600 [-] imm Node(54cbd6tx).get_segment(2)
2010-09-11 00:00:19-0600 [-] delivering segment(2)

Here is the comparable section of a run in which the download failed:

2010-09-11 00:05:55-0600 [-] imm Node(x36qlfft).get_segment(1)
2010-09-11 00:05:55-0600 [-] error requesting 60+24 from alg6u for si x36qlfft
2010-09-11 00:05:55-0600 [-] abandoning Share(sh0-on-alg6u)
2010-09-11 00:05:55-0600 [-] error requesting 60+24 from egjce for si x36qlfft
2010-09-11 00:05:55-0600 [-] abandoning Share(sh1-on-egjce)
2010-09-11 00:05:55-0600 [-] error requesting 60+24 from k6vb2 for si x36qlfft
2010-09-11 00:05:55-0600 [-] abandoning Share(sh2-on-k6vb2)
2010-09-11 00:05:55-0600 [-] error requesting 0+1024 from 7r4gd for si x36qlfft
2010-09-11 00:05:55-0600 [-] abandoning Share(sh3-on-7r4gd)
2010-09-11 00:05:55-0600 [-] storage: get_buckets x36qlfft7g5c7raim6y7yb25ju
2010-09-11 00:05:55-0600 [-] storage: get_buckets x36qlfft7g5c7raim6y7yb25ju
2010-09-11 00:05:55-0600 [-] got error from [fob7vqgd]
2010-09-11 00:05:55-0600 [-] got error from [rvsry4kn]
2010-09-11 00:05:55-0600 [-] got error from [ysbz4st7]
2010-09-11 00:05:55-0600 [-] got error from [xgru5adv]
2010-09-11 00:05:55-0600 [-] ShareFinder.loop: no_more_shares, ever
2010-09-11 00:05:55-0600 [-] ShareFinder.loop: no_more_shares, ever
2010-09-11 00:05:55-0600 [-] ShareFinder.loop: no_more_shares, ever
2010-09-11 00:05:55-0600 [-] ShareFinder.loop: no_more_shares, ever
2010-09-11 00:05:55-0600 [-] ran out of shares: complete= pending=Share(sh4-on-6jdsp),Share(sh5-on-b3llg) overdue= unused= need 3. Last failure: [Failure instance: Traceback (failure with no frames): <class 'foolscap.tokens.RemoteException'>: <RemoteException around '[Failure instance: Traceback: <class 'allmydata.test.no_network.IntentionalError'>: I was asked to break
        /Library/Python/2.6/site-packages/Twisted-10.1.0_r29874-py2.6-macosx-10.6-universal.egg/twisted/internet/base.py:789:runUntilCurrent
        /Library/Python/2.6/site-packages/foolscap-0.5.1-py2.6.egg/foolscap/eventual.py:26:_turn
        /Library/Python/2.6/site-packages/Twisted-10.1.0_r29874-py2.6-macosx-10.6-universal.egg/twisted/internet/defer.py:351:callback
        /Library/Python/2.6/site-packages/Twisted-10.1.0_r29874-py2.6-macosx-10.6-universal.egg/twisted/internet/defer.py:450:_startRunCallbacks
        --- <exception caught here> ---
        /Library/Python/2.6/site-packages/Twisted-10.1.0_r29874-py2.6-macosx-10.6-universal.egg/twisted/internet/defer.py:468:_runCallbacks
        /Users/zooko/playground/tahoe-lafs/trunk/src/allmydata/test/no_network.py:81:<lambda>
        /Users/zooko/playground/tahoe-lafs/trunk/src/allmydata/test/no_network.py:68:_call
        ]'>
        ]
Here is the last part of `_trial_temp/test.log` (created with `FLOGFILE=flog.out.bz2 FLOGLEVEL=1 FLOGTOTWISTED=1 PYTHONPATH=src/ trial --rterror allmydata.test.test_download.DownloadTest.test_lost_servers`) of a run in which the download succeeded: ``` 2010-09-11 00:00:19-0600 [-] imm Node(54cbd6tx).get_segment(1) 2010-09-11 00:00:19-0600 [-] error requesting 60+24 from 6jdsp for si 54cbd6tx 2010-09-11 00:00:19-0600 [-] abandoning Share(sh0-on-6jdsp) 2010-09-11 00:00:19-0600 [-] error requesting 60+24 from ysbz4 for si 54cbd6tx 2010-09-11 00:00:19-0600 [-] abandoning Share(sh1-on-ysbz4) 2010-09-11 00:00:19-0600 [-] error requesting 60+24 from k6vb2 for si 54cbd6tx 2010-09-11 00:00:19-0600 [-] abandoning Share(sh2-on-k6vb2) 2010-09-11 00:00:19-0600 [-] error requesting 0+1024 from alg6u for si 54cbd6tx 2010-09-11 00:00:19-0600 [-] abandoning Share(sh3-on-alg6u) 2010-09-11 00:00:19-0600 [-] got error from [xgru5adv] 2010-09-11 00:00:19-0600 [-] storage: get_buckets 54cbd6txyhbfqrdoclhpinsux4 2010-09-11 00:00:19-0600 [-] storage: get_buckets 54cbd6txyhbfqrdoclhpinsux4 2010-09-11 00:00:19-0600 [-] got error from [rvsry4kn] 2010-09-11 00:00:19-0600 [-] storage: get_buckets 54cbd6txyhbfqrdoclhpinsux4 2010-09-11 00:00:19-0600 [-] got error from [fob7vqgd] 2010-09-11 00:00:19-0600 [-] delivering segment(1) 2010-09-11 00:00:19-0600 [-] Segmentation got data: want [72-310), given [72-144), for segnum=1 2010-09-11 00:00:19-0600 [-] imm Node(54cbd6tx).get_segment(2) 2010-09-11 00:00:19-0600 [-] delivering segment(2) ``` Here is the comparable section of a run in which the download failed: ``` 2010-09-11 00:05:55-0600 [-] imm Node(x36qlfft).get_segment(1) 2010-09-11 00:05:55-0600 [-] error requesting 60+24 from alg6u for si x36qlfft 2010-09-11 00:05:55-0600 [-] abandoning Share(sh0-on-alg6u) 2010-09-11 00:05:55-0600 [-] error requesting 60+24 from egjce for si x36qlfft 2010-09-11 00:05:55-0600 [-] abandoning Share(sh1-on-egjce) 2010-09-11 00:05:55-0600 [-] error requesting 60+24 from k6vb2 for si x36qlfft 2010-09-11 00:05:55-0600 [-] abandoning Share(sh2-on-k6vb2) 2010-09-11 00:05:55-0600 [-] error requesting 0+1024 from 7r4gd for si x36qlfft 2010-09-11 00:05:55-0600 [-] abandoning Share(sh3-on-7r4gd) 2010-09-11 00:05:55-0600 [-] storage: get_buckets x36qlfft7g5c7raim6y7yb25ju 2010-09-11 00:05:55-0600 [-] storage: get_buckets x36qlfft7g5c7raim6y7yb25ju 2010-09-11 00:05:55-0600 [-] got error from [fob7vqgd] 2010-09-11 00:05:55-0600 [-] got error from [rvsry4kn] 2010-09-11 00:05:55-0600 [-] got error from [ysbz4st7] 2010-09-11 00:05:55-0600 [-] got error from [xgru5adv] 2010-09-11 00:05:55-0600 [-] ShareFinder.loop: no_more_shares, ever 2010-09-11 00:05:55-0600 [-] ShareFinder.loop: no_more_shares, ever 2010-09-11 00:05:55-0600 [-] ShareFinder.loop: no_more_shares, ever 2010-09-11 00:05:55-0600 [-] ShareFinder.loop: no_more_shares, ever 2010-09-11 00:05:55-0600 [-] ran out of shares: complete= pending=Share(sh4-on-6jdsp),Share(sh5-on-b3llg) overdue= unused= need 3. Last failure: [Failure instance: Traceback (failure with no frames): <class 'foolscap.tokens.RemoteException'>: <RemoteException around '[Failure instance: Traceback: <class 'allmydata.test.no_network.IntentionalError'>: I was asked to break /Library/Python/2.6/site-packages/Twisted-10.1.0_r29874-py2.6-macosx-10.6-universal.egg/twisted/internet/base.py:789:runUntilCurrent /Library/Python/2.6/site-packages/foolscap-0.5.1-py2.6.egg/foolscap/eventual.py:26:_turn /Library/Python/2.6/site-packages/Twisted-10.1.0_r29874-py2.6-macosx-10.6-universal.egg/twisted/internet/defer.py:351:callback /Library/Python/2.6/site-packages/Twisted-10.1.0_r29874-py2.6-macosx-10.6-universal.egg/twisted/internet/defer.py:450:_startRunCallbacks --- <exception caught here> --- /Library/Python/2.6/site-packages/Twisted-10.1.0_r29874-py2.6-macosx-10.6-universal.egg/twisted/internet/defer.py:468:_runCallbacks /Users/zooko/playground/tahoe-lafs/trunk/src/allmydata/test/no_network.py:81:<lambda> /Users/zooko/playground/tahoe-lafs/trunk/src/allmydata/test/no_network.py:68:_call ]'> ] ```
david-sarah@jacaranda.org commented 2010-09-12 00:52:32 +00:00
Author
Owner
Copy link

In changeset:6c4ba62c5d3a7624:

test_download.py: simplify and possibly fix test_lost_servers; refs #1197
In changeset:6c4ba62c5d3a7624: ``` test_download.py: simplify and possibly fix test_lost_servers; refs #1197 ```
davidsarah commented 2010-09-12 01:42:31 +00:00
Author
Owner
Copy link

That seems to have worked.

That seems to have worked.
zooko commented 2010-09-12 07:25:32 +00:00
Author
Owner
Copy link

reviewed. Thanks!! :-)

reviewed. Thanks!! :-)
tahoe-lafs added the
fixed
 label 2010-09-12 07:25:32 +00:00
zooko closed this issue 2010-09-12 07:25:32 +00:00
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
No results found.
No results found.
Labels
Clear labels   
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

catch-all for anything that can be fixed by writing code but isn't classified better

  
code-dirnodes

anything involving tahoe directories

  
code-encoding

immutable-file encoding format/layout, cap format, encoding/decoding algorithms

  
code-frontend

general frontend things: new user-facing interfaces, FTP/SFTP servers, FUSE-like interfaces

  
code-frontend-cli

CLI tools

  
code-frontend-ftp-sftp

   
code-frontend-magic-folder

   
code-frontend-web

webapi interfaces, user-facing "WUI" interfaces

  
code-mutable

anything involving mutable files: encoding/decoding, share format

  
code-network

Introducer, locating storage servers, establishing/maintaining connections to them

  
code-nodeadmin

node startup/shutdown, tools to create nodes, logging tools, management/monitoring tools, manhole, disk-space-limiting tools

  
code-peerselection

server selection/sorting algorithm, rebalancing code, allocation policy, swarming-download

  
code-storage

storage-server implementation, share-storage directory layout, client-to-server share transfer protocol

  
contrib

problems with non-core things that live in the source:contrib/ directory

  
critical

   
defect

   
dev-infrastructure

things that help us build Tahoe: buildbot, automated speed/memory/code-coverage tests and results-displayers, IRC channels, mailing lists, this Trac instance

  
documentation

docs items. Also use 'docs' keyword on tickets in more specific components.

  
duplicate

   
enhancement

   
fixed

   
invalid

   
major

   
minor

   
n/a

   
normal

   
operational

things involved in running a tahoe grid, external tools to monitor/maintain a grid (like "nodeadmin" but larger-scale). Was also used for issues with the allmydata.com grid.

  
packaging

setup.py script, library dependencies, binary packages, licensing, installation instructions

  
somebody else's problem

   
supercritical

   
task

   
trivial

   
unknown

Uncategorized. All tickets default to this component until someone updates it.

  
was already fixed

   
website

things about the tahoe-lafs.org website (and sometimes this Trac instance, shared with 'dev-infrastructure')

  
wontfix

   
worksforme
No labels
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
Milestone
Clear milestone
No items
No milestone
1.8.0
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference: tahoe-lafs/trac-2024-07-25#1197
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?