[tahoe-dev] debug info of ticket #1670

Wed Apr 11 14:29:58 UTC 2012

hi,all
As we always encounter the error in ticket #1670.
here is the debug log when it happens again:

local#38800 18:29:35.999: Publish(zsr26): starting
local#38801 18:29:35.999: starting publish, datalen is 327
local#38802 18:29:35.999: new seqnum will be 2
local#38803 18:29:36.000: building encoding parameters for file
local#38804 18:29:36.000: got segsize 328
local#38805 18:29:36.000: got 1 segments
local#38806 18:29:36.000: got tail segment size 327
local#38807 18:29:36.000: got start segment 0
local#38808 18:29:36.000: got end segment 0
local#38809 18:29:36.000: current goal: before update: , sh0 to [mpdeyxq3],
sh1 to [xgb2iimw], sh2 to [lm54czaj]
local#38810 18:29:36.000: we are planning to push new seqnum=#2
local#38811 18:29:36.000: current goal: after update: , sh0 to [mpdeyxq3],
sh1 to [xgb2iimw], sh2 to [lm54czaj], sh3 to [
ijpt6rlf]
local#38812 18:29:36.000: we are planning to push new seqnum=#2
local#38816 18:29:36.001: Starting push
local#38817 18:29:36.001: Pushing segment 1 of 1
local#38818 18:29:36.034: _got_write_answer from xgb2iimw, share 1
local#38819 18:29:36.034: found the following surprise shares: set([])
local#38820 18:29:36.034: wrote successfully: adding new share to servermap
local#38821 18:29:36.036: _got_write_answer from lm54czaj, share 2
local#38822 18:29:36.036: found the following surprise shares: set([])
local#38823 18:29:36.036: wrote successfully: adding new share to servermap
local#38824 18:29:36.039: _got_write_answer from mpdeyxq3, share 0
local#38825 18:29:36.039: found the following surprise shares: set([])
local#38826 18:29:36.039: wrote successfully: adding new share to servermap
local#38827 18:29:36.041: _got_write_answer from ijpt6rlf, share 3
local#38828 18:29:36.042: found the following surprise shares: set([])
local#38829 18:29:36.042: our testv failed, so the write did not happen
*>>here, we check the storage server, the debug log shows:
>>local#6283 18:29:57.794: storage: slot_writev zsr2655gojgzwe3gtxkelysnam
>>local#6284 18:29:57.794: testv failed: [3]: [(0, 1, 'eq', '')]*
local#38830 18:29:36.042: Publish failed with UncoordinatedWriteError
local#38831 18:29:38.638: doing modify
local#38832 18:29:38.638: SharemapUpdater(zsr26): starting (MODE_CHECK)
local#38833 18:29:38.639: sending query to [mpdeyxq3], readsize=1000
local#38834 18:29:38.640: sending query to [oimhcuze], readsize=1000
local#38835 18:29:38.642: sending query to [u3lncyyd], readsize=1000
local#38836 18:29:38.644: sending query to [3kugxfcs], readsize=1000
local#38837 18:29:38.646: sending query to [ptlknl6f], readsize=1000
local#38838 18:29:38.648: sending query to [xgb2iimw], readsize=1000
local#38839 18:29:38.650: sending query to [lm54czaj], readsize=1000
local#38840 18:29:38.651: sending query to [kfet3cpe], readsize=1000
local#38841 18:29:38.653: sending query to [ijpt6rlf], readsize=1000
local#38842 18:29:38.659: got result from [kfet3cpe], 0 shares
local#38843 18:29:38.659: _check_for_done, mode is 'MODE_CHECK', 8 queries
outstanding, 0 extra peers available, 8 'must
query' peers left, need_privkey=False
local#38844 18:29:38.659: 8 'must query' peers left
local#38845 18:29:38.659: _got_results done
local#38846 18:29:38.659: _check_for_done, mode is 'MODE_CHECK', 8 queries
outstanding, 0 extra peers available, 8 'must
query' peers left, need_privkey=False
local#38847 18:29:38.659: 8 'must query' peers left
local#38848 18:29:38.662: got result from [mpdeyxq3], 1 shares
[INCIDENT-TRIGGER]
local#38849 18:29:38.909: _got_results done
local#38850 18:29:38.909: got result from [3kugxfcs], 0 shares
local#38851 18:29:38.909: _check_for_done, mode is 'MODE_CHECK', 7 queries
outstanding, 0 extra peers available, 7 'must
query' peers left, need_privkey=False
local#38852 18:29:38.909: 7 'must query' peers left
local#38853 18:29:38.909: _got_results done
local#38854 18:29:38.910: _check_for_done, mode is 'MODE_CHECK', 7 queries
outstanding, 0 extra peers available, 7 'must
query' peers left, need_privkey=False
local#38855 18:29:38.910: 7 'must query' peers left
local#38856 18:29:38.910: got result from [oimhcuze], 0 shares
local#38857 18:29:38.910: _check_for_done, mode is 'MODE_CHECK', 6 queries
outstanding, 0 extra peers available, 6 'must
query' peers left, need_privkey=False
local#38858 18:29:38.910: 6 'must query' peers left
local#38859 18:29:38.910: _got_results done
local#38860 18:29:38.910: _check_for_done, mode is 'MODE_CHECK', 6 queries
outstanding, 0 extra peers available, 6 'must
query' peers left, need_privkey=False
local#38861 18:29:38.911: 6 'must query' peers left
local#38862 18:29:39.018: _got_results: got shnum #0 from peerid mpdeyxq3
local#38863 18:29:39.018:  found valid version 2-pza7 from mpdeyxq3-sh0:
2-4/328/327
local#38864 18:29:39.018: _check_for_done, mode is 'MODE_CHECK', 5 queries
outstanding, 0 extra peers available, 5 'must
query' peers left, need_privkey=False
local#38865 18:29:39.018: 5 'must query' peers left
local#38866 18:29:39.018: _check_for_done, mode is 'MODE_CHECK', 5 queries
outstanding, 0 extra peers available, 5 'must
query' peers left, need_privkey=False
local#38867 18:29:39.018: 5 'must query' peers left
local#38868 18:29:39.022: got result from [ptlknl6f], 0 shares
local#38869 18:29:39.022: _check_for_done, mode is 'MODE_CHECK', 4 queries
outstanding, 0 extra peers available, 4 'must
query' peers left, need_privkey=False
local#38870 18:29:39.022: 4 'must query' peers left
local#38871 18:29:39.022: _got_results done
local#38872 18:29:39.022: _check_for_done, mode is 'MODE_CHECK', 4 queries
outstanding, 0 extra peers available, 4 'must
query' peers left, need_privkey=False
local#38873 18:29:39.022: 4 'must query' peers left
local#38874 18:29:39.024: got result from [xgb2iimw], 1 shares
local#38875 18:29:39.024: _got_results done
local#38876 18:29:39.025: got result from [lm54czaj], 1 shares
local#38877 18:29:39.025: _got_results done
local#38878 18:29:39.026: got result from [u3lncyyd], 0 shares
local#38879 18:29:39.026: _check_for_done, mode is 'MODE_CHECK', 3 queries
outstanding, 0 extra peers available, 3 'must
query' peers left, need_privkey=False
local#38880 18:29:39.026: 3 'must query' peers left
local#38881 18:29:39.026: _got_results done
local#38882 18:29:39.026: _check_for_done, mode is 'MODE_CHECK', 3 queries
outstanding, 0 extra peers available, 3 'must
query' peers left, need_privkey=False
local#38883 18:29:39.026: 3 'must query' peers left
local#38884 18:29:39.028: got result from [ijpt6rlf], 1 shares
local#38885 18:29:39.028: _got_results done
local#38886 18:29:39.031: _got_results: got shnum #1 from peerid xgb2iimw
local#38887 18:29:39.031:  found valid version 2-pza7 from xgb2iimw-sh1:
2-4/328/327
local#38888 18:29:39.031: _check_for_done, mode is 'MODE_CHECK', 2 queries
outstanding, 0 extra peers available, 2 'must
query' peers left, need_privkey=False
local#38889 18:29:39.031: 2 'must query' peers left
local#38890 18:29:39.031: _check_for_done, mode is 'MODE_CHECK', 2 queries
outstanding, 0 extra peers available, 2 'must
query' peers left, need_privkey=False
local#38891 18:29:39.032: 2 'must query' peers left
local#38892 18:29:39.032: _got_results: got shnum #2 from peerid lm54czaj
local#38893 18:29:39.032:  found valid version 2-pza7 from lm54czaj-sh2:
2-4/328/327
local#38894 18:29:39.032: _check_for_done, mode is 'MODE_CHECK', 1 queries
outstanding, 0 extra peers available, 1 'must
query' peers left, need_privkey=False
local#38895 18:29:39.032: 1 'must query' peers left
local#38896 18:29:39.032: _check_for_done, mode is 'MODE_CHECK', 1 queries
outstanding, 0 extra peers available, 1 'must
query' peers left, need_privkey=False
local#38897 18:29:39.032: 1 'must query' peers left
local#38898 18:29:39.034: _got_results: got shnum #3 from peerid ijpt6rlf
local#38899 18:29:39.035:  found valid version 1-kgqs from ijpt6rlf-sh3:
2-4/0/0
local#38900 18:29:39.035: _check_for_done, mode is 'MODE_CHECK', 0 queries
outstanding, 0 extra peers available, 0 'must
query' peers left, need_privkey=False
local#38901 18:29:39.035: all queries are retired, no extra peers: done
local#38902 18:29:39.035: servermap: 3*seq2-pza7/1*seq1-kgqs
*>>here the servermap cnfused me a lot.
>>it indicates 2 versions?but "seq1-kgqs" only have one shares, does this
result in the assert error because download needs number shares greater
than  K.
>>BTW, we configured "shares.needed=2, shares.happy=3, shares.total=10",
does it matters the problem? since the default is 3:7:10.*
local#38903 18:29:39.035: _check_for_done, mode is 'MODE_CHECK', 0 queries
outstanding, 0 extra peers available, 0 'must
query' peers left, need_privkey=False
local#38904 18:29:39.035: but we're not running

*And the status page show like this:*
publish zsr2655gojgzwe3gtxkelysnam No 327B 75.0% Sending Shares: 3 placed
out of 4, 1 messages outstanding

Regards
-- 
huangjun
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://tahoe-lafs.org/pipermail/tahoe-dev/attachments/20120411/bf3ea23e/attachment.html>