Ticket #1655: incident-2012-03-09--05-23-19Z-vsxjgbi.txt

File incident-2012-03-09--05-23-19Z-vsxjgbi.txt, 66.7 KB (added by ianchov, at 2012-03-10T07:30:28Z)

Last incidents for Uncoordinated Write Error

Line 
1Application versions (embedded in logfile):
2          Nevow: 0.10.0
3        Twisted: 10.1.0
4allmydata-tahoe: 1.9.1
5       foolscap: 0.6.3
6           mock: 0.8.0rc2
7       platform: Windows-7-6.1.7601-SP1
8      pyOpenSSL: 0.12
9         pyasn1: unknown
10       pycrypto: 2.4
11     pycryptopp: 0.5.29
12         python: 2.6.6
13     setuptools: 0.6c16dev3
14     simplejson: 2.3.2
15        sqlite3: 2.4.1
16        twisted: 10.1.0
17           zfec: 1.4.7-r362
18 zope.interface: unknown
19PID: 3912
20
21local#0 06:23:13.255: Node constructed. allmydata-tahoe: 1.9.1,
22foolscap: 0.6.3,
23pycryptopp: 0.5.29,
24zfec: 1.4.7-r362,
25Twisted: 10.1.0,
26Nevow: 0.10.0,
27zope.interface: unknown,
28python: 2.6.6,
29platform: Windows-7-6.1.7601-SP1,
30pyOpenSSL: 0.12,
31simplejson: 2.3.2,
32pycrypto: 2.4,
33pyasn1: unknown,
34mock: 0.8.0rc2,
35sqlite3: 2.4.1 [sqlite 3.5.9],
36setuptools: 0.6c16dev3
37
38local#1 06:23:13.256: StorageServer created
39local#2 06:23:13.289: want to subscribe, but no introducer yet
40local#3 06:23:13.289: init_web(webport=tcp:3456:interface=127.0.0.1)
41local#4 06:23:13.371: Loaded.
42local#5 06:23:13.371: Log opened.
43local#6 06:23:13.371: twistd 10.1.0 (C:\Python26\python.exe 2.6.6) starting up.
44local#7 06:23:13.371: reactor class: twisted.internet.selectreactor.SelectReactor.
45local#8 06:23:13.372: foolscap.pb.Listener starting on 55392
46local#9 06:23:13.372: Starting factory <Listener at 0x48cd5c8 on 55392 with tubs aty4re3a3ygvb6a2gext5vbcgdzs4ihk>
47local#10 06:23:13.372: nevow.appserver.NevowSite starting on 3456
48local#11 06:23:13.372: Starting factory <nevow.appserver.NevowSite instance at 0x0000000002708408>
49local#12 06:23:13.372: Node.startService
50local#13 06:23:13.372: My pid: 3912
51local#14 06:23:13.374: Node._startService
52local#15 06:23:13.374: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to hpd3hn75ggwujdsacpd47r4yj6tahutj
53local#16 06:23:13.374: connectTCP to ('rosenkeller.org', 32121)
54local#17 06:23:13.374: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to hpd3hn75] at 0x0000000002706B70>
55local#18 06:23:13.375: twisted.internet.protocol.DatagramProtocol starting on 57066
56local#19 06:23:13.375: Starting protocol <twisted.internet.protocol.DatagramProtocol instance at 0x000000000270B488>
57local#20 06:23:13.385: (Port 57066 Closed)
58local#21 06:23:13.385: Stopping protocol <twisted.internet.protocol.DatagramProtocol instance at 0x000000000270B488>
59local#22 06:23:13.448: Negotiation started
60local#26 06:23:13.490: Tub location set to 78.83.249.174
61local#27 06:23:13.490: client running
62local#28 06:23:13.490: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to sqlcmsbk34qui3vpstyokohufzffwkt2
63local#29 06:23:13.490: connectTCP to ('184.106.205.58', 46598)
64local#30 06:23:13.490: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to sqlcmsbk] at 0x000000000270EA20>
65local#31 06:23:13.492: want to publish, but no introducer yet
66local#32 06:23:13.494: want to publish, but no introducer yet
67local#33 06:23:13.494: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to duszrv4xk7yinbyjrbxiirvepoik7jhm
68local#34 06:23:13.494: connectTCP to ('rosenkeller.org', 42247)
69local#35 06:23:13.494: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to duszrv4x] at 0x000000000270EE10>
70local#41 06:23:14.540: Negotiation started
71local#45 06:23:14.540: Negotiation started
72local#67 06:23:14.957: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': '5f276dfe842c13f4 5'}
73local#70 06:23:14.957: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to hpd3hn75] at 0x0000000002706B70> won
74local#71 06:23:14.957: connectorFinished (<foolscap.negotiate.TubConnector object at 0x0000000002706B38 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to hpd3hn75ggwujdsacpd47r4yj6tahutj>)
75local#74 06:23:15.012: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': 'cf3b9daa4b1db809 1'}
76local#77 06:23:15.012: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to duszrv4x] at 0x000000000270EE10> won
77local#78 06:23:15.012: connectorFinished (<foolscap.negotiate.TubConnector object at 0x000000000270EDA0 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to duszrv4xk7yinbyjrbxiirvepoik7jhm>)
78local#79 06:23:15.013: <Uploader #1>: got helper connection, getting versions
79local#85 06:23:15.417: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': 'ecd6175f02242f10 6'}
80local#88 06:23:15.417: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to sqlcmsbk] at 0x000000000270EA20> won
81local#89 06:23:15.417: connectorFinished (<foolscap.negotiate.TubConnector object at 0x000000000270E6D8 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to sqlcmsbk34qui3vpstyokohufzffwkt2>)
82local#90 06:23:15.559: connected to introducer, getting versions
83local#91 06:23:15.703: got introducer version: {'http://allmydata.org/tahoe/protocols/introducer/v1': {}, 'application-version': 'allmydata-tahoe/1.8.3'}
84local#92 06:23:15.861: received 14 announcements
85local#93 06:23:15.861: announcement for [storage]: ('pb://huadamis74e2mwtgiq23a2jm5l7m72hi@server.palatinus.cz:9001/td6smgu5oavsihyddp5pyul2gutjk4al', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'slush@centrum.cz-future', 'allmydata-tahoe/1.8.3', '1.0.0')
86local#94 06:23:15.862: announcement for [storage]: ('pb://b55ww7wazcrwu4owhlxpmvx6qvr4p3iy@bach-home.ath.cx:6001,127.0.0.1:6001/zgqskear5ddhhy45zflqrpxwdgaf2ivv', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'pascal.bach@gmx.ch-Horus', 'allmydata-tahoe/1.9.1', '1.0.0')
87local#95 06:23:15.862: announcement for [storage]: ('pb://aty4re3a3ygvb6a2gext5vbcgdzs4ihk@78.83.249.174/pcdvfeyl54xucaynoytisncf7wrqxknw', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'ianchov@gmail.com', 'allmydata-tahoe/1.9.1', '1.0.0')
88local#96 06:23:15.862: announcement for [storage]: ('pb://jbrse33y3gmtpauhhgfsrti4o4mzlcsk@68.233.149.2:8766,127.0.0.1:8766/5uicwx4grz4kufuuy5x4fzckd4pdmpt2', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'jharris@harrisdev.com-Cat', 'allmydata-tahoe/1.8.2', '1.0.0')
89local#97 06:23:15.862: announcement for [storage]: ('pb://pmitrhwg7hminstxvijbyzefsovwq7hf@gratch.willden.org:45625/tlh2ptoep3inaxbfminldcq4cbdj72xq', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'shawn@willden.org-gratch', 'allmydata-tahoe/1.9.1', '1.0.0')
90local#98 06:23:15.862: announcement for [storage]: ('pb://inxoy6uiulkr2uwm6s3rmz6jzyiywkvi@cerezal.selfip.net:8098/aqkqublpeblnfnp7phnies7oght36l7o', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'cerezal@gmx.net-cerezal', 'allmydata-tahoe/1.9.1', '1.0.0')
91local#99 06:23:15.862: announcement for [storage]: ('pb://gbytbnxw2hkbpjslf7mevzejefmdomtb@rhp997.dyndns.org:33386/f6mmdhhwjhsz7inwewfzpy6ptjat5mc6', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'steve.dodson@gmail.com-hiro', 'allmydata-tahoe/1.7.1', '1.0.0')
92local#100 06:23:15.862: announcement for [storage]: ('pb://baeq4skxppta2cc6wnjfv7k2uu7ms4b6@sln.superlumin.com:33892/2oo5qrfqqg6ejbuioyfmx2fadq56lb4c', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'bradrupp@gmail.com-sln', 'allmydata-tahoe/1.8.3', '1.0.0')
93local#101 06:23:15.862: announcement for [storage]: ('pb://kvj2xrmmti3wp2albm3mmo3ulead5fy2@kruemi.homelinux.org:8098,192.168.10.10:8098,10.248.5.3:8098,127.0.0.1:8098/ma6dc7ebq3xt7t6wsbionskb57ioldkh', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'marco.tedaldi@gmail.com', 'allmydata-tahoe/1.8.3', '1.0.0')
94local#102 06:23:15.862: announcement for [storage]: ('pb://hpd3hn75ggwujdsacpd47r4yj6tahutj@rosenkeller.org:32121/j2zqmgd7bg7rd6icryxn2g4ym4bncoam', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'christoph@rosenkeller.org-bender', 'allmydata-tahoe/1.8.3', '1.0.0')
95local#103 06:23:15.864: announcement for [storage]: ('pb://vifimgiwol6shdmyoxyqvet5oz6dqnt5@earney.homedns.org:49244/6qa3vi342juxqkgxorauxdpaqxe47jwa', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'billy.earney@gmail.com', 'allmydata-tahoe/1.8.3', '1.0.0')
96local#104 06:23:15.864: announcement for [storage]: ('pb://g4xvpwqadyiwfu26qfxkgmjjxmony52p@63.233.155.10:33386/3yshj7nceglj7dvejy6qnwtmidmdkuxs', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'steve.dodson@gmail.com-rhp997', 'allmydata-tahoe/1.8.3', '1.0.0')
97local#105 06:23:15.864: announcement for [storage]: ('pb://qivwuhf6cnon45sld7lq5a3iugsjjqmw@if3-1.no-ip.org:33892/6tekcmlfjtwr7634e4blpe3acecjp7ei', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'bradrupp@gmail.com-if3-1', 'allmydata-tahoe/1.8.3', '1.0.0')
98local#106 06:23:15.864: announcement for [storage]: ('pb://kqyu52yzkipbt5ktyu6x56s6isi2khyc@foo.asia-king.co.uk:3917/h66p63tgqkfodqxpos3pt2emjziov6bp', 'storage', 'RIStorageServer.tahoe.allmydata.com', 'sabotrax@gmail.com', 'allmydata-tahoe/1.9.1', '1.0.0')
99local#107 06:23:15.865: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to huadamis74e2mwtgiq23a2jm5l7m72hi
100local#108 06:23:15.865: connectTCP to ('server.palatinus.cz', 9001)
101local#109 06:23:15.865: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to huadamis] at 0x000000000271F080>
102local#110 06:23:15.865: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to b55ww7wazcrwu4owhlxpmvx6qvr4p3iy
103local#111 06:23:15.865: connectTCP to ('127.0.0.1', 6001)
104local#112 06:23:15.865: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to b55ww7wa] at 0x000000000271F2B0>
105local#113 06:23:15.865: connectTCP to ('bach-home.ath.cx', 6001)
106local#114 06:23:15.865: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to b55ww7wa] at 0x000000000271F358>
107local#115 06:23:15.865: Negotiation started
108local#116 06:23:15.865: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to jbrse33y3gmtpauhhgfsrti4o4mzlcsk
109local#117 06:23:15.865: connectTCP to ('127.0.0.1', 8766)
110local#118 06:23:15.865: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to jbrse33y] at 0x0000000002723198>
111local#119 06:23:15.865: connectTCP to ('68.233.149.2', 8766)
112local#120 06:23:15.865: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to jbrse33y] at 0x0000000002723240>
113local#121 06:23:15.865: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to pmitrhwg7hminstxvijbyzefsovwq7hf
114local#122 06:23:15.865: connectTCP to ('gratch.willden.org', 45625)
115local#123 06:23:15.865: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to pmitrhwg] at 0x0000000002723400>
116local#124 06:23:15.867: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to inxoy6uiulkr2uwm6s3rmz6jzyiywkvi
117local#125 06:23:15.867: connectTCP to ('cerezal.selfip.net', 8098)
118local#126 06:23:15.867: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to inxoy6ui] at 0x00000000027235F8>
119local#127 06:23:15.867: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to gbytbnxw2hkbpjslf7mevzejefmdomtb
120local#128 06:23:15.867: connectTCP to ('rhp997.dyndns.org', 33386)
121local#129 06:23:15.867: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to gbytbnxw] at 0x00000000027237F0>
122local#130 06:23:15.867: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to baeq4skxppta2cc6wnjfv7k2uu7ms4b6
123local#131 06:23:15.867: connectTCP to ('sln.superlumin.com', 33892)
124local#132 06:23:15.867: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to baeq4skx] at 0x00000000027239E8>
125local#133 06:23:15.867: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to kvj2xrmmti3wp2albm3mmo3ulead5fy2
126local#134 06:23:15.867: connectTCP to ('127.0.0.1', 8098)
127local#135 06:23:15.867: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kvj2xrmm] at 0x0000000002723B38>
128local#136 06:23:15.868: connectTCP to ('10.248.5.3', 8098)
129local#137 06:23:15.868: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kvj2xrmm] at 0x0000000002723DA0>
130local#138 06:23:15.868: connectTCP to ('192.168.10.10', 8098)
131local#139 06:23:15.868: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kvj2xrmm] at 0x0000000002723EB8>
132local#140 06:23:15.868: connectTCP to ('kruemi.homelinux.org', 8098)
133local#141 06:23:15.868: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kvj2xrmm] at 0x0000000002723FD0>
134local#142 06:23:15.868: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to vifimgiwol6shdmyoxyqvet5oz6dqnt5
135local#143 06:23:15.868: connectTCP to ('earney.homedns.org', 49244)
136local#144 06:23:15.868: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to vifimgiw] at 0x000000000272A2E8>
137local#145 06:23:15.868: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to g4xvpwqadyiwfu26qfxkgmjjxmony52p
138local#146 06:23:15.868: connectTCP to ('63.233.155.10', 33386)
139local#147 06:23:15.868: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to g4xvpwqa] at 0x000000000272A470>
140local#148 06:23:15.868: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to qivwuhf6cnon45sld7lq5a3iugsjjqmw
141local#149 06:23:15.868: connectTCP to ('if3-1.no-ip.org', 33892)
142local#150 06:23:15.868: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to qivwuhf6] at 0x000000000272A6D8>
143local#151 06:23:15.868: TubConnector created from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to kqyu52yzkipbt5ktyu6x56s6isi2khyc
144local#152 06:23:15.868: connectTCP to ('foo.asia-king.co.uk', 3917)
145local#153 06:23:15.868: Starting factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kqyu52yz] at 0x000000000272A8D0>
146local#154 06:23:15.874: got connection to aty4re3a, getting versions
147local#155 06:23:15.877: aty4re3a provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 325612279296L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.9.1'}
148local#156 06:23:15.924: got connection to hpd3hn75, getting versions
149local#157 06:23:15.964: Negotiation started
150local#161 06:23:15.986: hpd3hn75 provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 1309676035072L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.8.3'}
151local#167 06:23:16.059: Negotiation started
152local#171 06:23:16.078: Negotiation started
153local#180 06:23:16.138: Negotiation started
154local#187 06:23:16.323: Negotiation started
155local#194 06:23:16.345: Negotiation started
156local#198 06:23:16.391: Negotiation started
157local#209 06:23:16.515: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': '9c7e819cf82f4771 31'}
158local#212 06:23:16.516: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to huadamis] at 0x000000000271F080> won
159local#213 06:23:16.516: connectorFinished (<foolscap.negotiate.TubConnector object at 0x000000000271F0B8 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to huadamis74e2mwtgiq23a2jm5l7m72hi>)
160local#229 06:23:16.591: got connection to huadamis, getting versions
161local#232 06:23:16.592: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': '5c7b22442c131707 3'}
162local#235 06:23:16.592: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to b55ww7wa] at 0x000000000271F358> won
163local#236 06:23:16.592: told to disconnect
164local#237 06:23:16.592: connectorFinished (<foolscap.negotiate.TubConnector object at 0x000000000271F1D0 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to b55ww7wazcrwu4owhlxpmvx6qvr4p3iy>)
165local#238 06:23:16.592: Stopping factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to b55ww7wa] at 0x000000000271F2B0>
166local#239 06:23:16.592: connectorFinished (<foolscap.negotiate.TubConnector object at 0x000000000271F1D0 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to b55ww7wazcrwu4owhlxpmvx6qvr4p3iy>)
167local#240 06:23:16.667: got connection to b55ww7wa, getting versions
168local#241 06:23:16.677: huadamis provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 1024776559616L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.8.3'}
169local#242 06:23:16.736: b55ww7wa provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 787091998720L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.9.1'}
170local#243 06:23:16.831: Negotiation started
171local#247 06:23:16.869: Stopping factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to jbrse33y] at 0x0000000002723198>
172local#248 06:23:16.888: Stopping factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kvj2xrmm] at 0x0000000002723B38>
173local#249 06:23:16.897: Negotiation started
174local#253 06:23:16.954: Negotiation started
175local#259 06:23:16.971: startENCRYPTED(isClient=True, encrypted=True)
176local#260 06:23:16.971: startTLS, client=True
177local#261 06:23:16.971: Negotiate.sendHello (isClient=True): {'my-incarnation': '9a6c03436c11e75e', 'last-connection': 'none 0', 'my-tub-id': 'aty4re3a3ygvb6a2gext5vbcgdzs4ihk', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
178local#262 06:23:17.007: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: f61601be67f0278b\r\nmy-tub-id: inxoy6uiulkr2uwm6s3rmz6jzyiywkvi\r\n\r\n'
179local#263 06:23:17.007: evaluateHello(isClient=True): offer={'my-tub-id': 'inxoy6uiulkr2uwm6s3rmz6jzyiywkvi', 'my-incarnation': 'f61601be67f0278b', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
180local#264 06:23:17.007: iAmTheMaster: False
181local#265 06:23:17.019: dataReceived(isClient=True,phase=0,options={}): 'HTTP/1.1 101 Switching Protocols\r\nUpgrade: TLS/1.0, PB/1.0\r\nConnection: Upgrade\r\n\r\n'
182local#266 06:23:17.020: handlePLAINTEXTClient: header='HTTP/1.1 101 Switching Protocols
183Upgrade: TLS/1.0, PB/1.0
184Connection: Upgrade'
185local#267 06:23:17.020: startENCRYPTED(isClient=True, encrypted=True)
186local#268 06:23:17.020: startTLS, client=True
187local#269 06:23:17.020: Negotiate.sendHello (isClient=True): {'my-incarnation': '9a6c03436c11e75e', 'last-connection': 'none 0', 'my-tub-id': 'aty4re3a3ygvb6a2gext5vbcgdzs4ihk', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
188local#270 06:23:17.085: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: e02e66597cd725d7\r\nmy-tub-id: pmitrhwg7hminstxvijbyzefsovwq7hf\r\n\r\n'
189local#271 06:23:17.085: evaluateHello(isClient=True): offer={'my-tub-id': 'pmitrhwg7hminstxvijbyzefsovwq7hf', 'my-incarnation': 'e02e66597cd725d7', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
190local#272 06:23:17.085: iAmTheMaster: False
191local#273 06:23:17.135: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: 7807f4a8f5d836a4\r\nmy-tub-id: baeq4skxppta2cc6wnjfv7k2uu7ms4b6\r\n\r\n'
192local#274 06:23:17.135: evaluateHello(isClient=True): offer={'my-tub-id': 'baeq4skxppta2cc6wnjfv7k2uu7ms4b6', 'my-incarnation': '7807f4a8f5d836a4', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
193local#275 06:23:17.135: iAmTheMaster: False
194local#276 06:23:17.148: dataReceived(isClient=True,phase=0,options={}): 'HTTP/1.1 101 Switching Protocols\r\nUpgrade: TLS/1.0, PB/1.0\r\nConnection: Upgrade\r\n\r\n'
195local#277 06:23:17.148: handlePLAINTEXTClient: header='HTTP/1.1 101 Switching Protocols
196Upgrade: TLS/1.0, PB/1.0
197Connection: Upgrade'
198local#278 06:23:17.148: startENCRYPTED(isClient=True, encrypted=True)
199local#279 06:23:17.148: startTLS, client=True
200local#280 06:23:17.148: Negotiate.sendHello (isClient=True): {'my-incarnation': '9a6c03436c11e75e', 'last-connection': 'none 0', 'my-tub-id': 'aty4re3a3ygvb6a2gext5vbcgdzs4ihk', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
201local#281 06:23:17.180: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: 03a292f2a643574e\r\nmy-tub-id: kvj2xrmmti3wp2albm3mmo3ulead5fy2\r\n\r\n'
202local#282 06:23:17.181: evaluateHello(isClient=True): offer={'my-tub-id': 'kvj2xrmmti3wp2albm3mmo3ulead5fy2', 'my-incarnation': '03a292f2a643574e', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
203local#283 06:23:17.181: iAmTheMaster: False
204local#284 06:23:17.181: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: 93a15c061ffd0b07\r\nmy-tub-id: g4xvpwqadyiwfu26qfxkgmjjxmony52p\r\n\r\n'
205local#285 06:23:17.181: evaluateHello(isClient=True): offer={'my-tub-id': 'g4xvpwqadyiwfu26qfxkgmjjxmony52p', 'my-incarnation': '93a15c061ffd0b07', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
206local#286 06:23:17.183: iAmTheMaster: False
207local#287 06:23:17.206: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: 8703d6eb24bbf81a\r\nmy-tub-id: kqyu52yzkipbt5ktyu6x56s6isi2khyc\r\n\r\n'
208local#288 06:23:17.206: evaluateHello(isClient=True): offer={'my-tub-id': 'kqyu52yzkipbt5ktyu6x56s6isi2khyc', 'my-incarnation': '8703d6eb24bbf81a', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
209local#289 06:23:17.206: iAmTheMaster: False
210local#290 06:23:17.303: dataReceived(isClient=True,phase=0,options={}): 'HTTP/1.1 101 Switching Protocols\r\nUpgrade: TLS/1.0, PB/1.0\r\nConnection: Upgrade\r\n\r\n'
211local#291 06:23:17.303: handlePLAINTEXTClient: header='HTTP/1.1 101 Switching Protocols
212Upgrade: TLS/1.0, PB/1.0
213Connection: Upgrade'
214local#292 06:23:17.303: startENCRYPTED(isClient=True, encrypted=True)
215local#293 06:23:17.303: startTLS, client=True
216local#294 06:23:17.305: Negotiate.sendHello (isClient=True): {'my-incarnation': '9a6c03436c11e75e', 'last-connection': 'none 0', 'my-tub-id': 'aty4re3a3ygvb6a2gext5vbcgdzs4ihk', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
217local#295 06:23:17.305: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: f61601be67f0278b 7\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
218local#296 06:23:17.305: handleDECIDING(isClient=True): banana-decision-version: 3
219current-connection: f61601be67f0278b 7
220initial-vocab-table-index: 1 bb33
221local#297 06:23:17.305: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': 'f61601be67f0278b 7'}
222local#298 06:23:17.305: Negotiate.switchToBanana(isClient=True)
223local#299 06:23:17.305: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
224local#300 06:23:17.305: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to inxoy6ui] at 0x00000000027235F8> won
225local#301 06:23:17.305: connectorFinished (<foolscap.negotiate.TubConnector object at 0x0000000002723588 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to inxoy6uiulkr2uwm6s3rmz6jzyiywkvi>)
226local#302 06:23:17.443: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: 03a292f2a643574e 2\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
227local#303 06:23:17.443: handleDECIDING(isClient=True): banana-decision-version: 3
228current-connection: 03a292f2a643574e 2
229initial-vocab-table-index: 1 bb33
230local#304 06:23:17.443: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': '03a292f2a643574e 2'}
231local#305 06:23:17.443: Negotiate.switchToBanana(isClient=True)
232local#306 06:23:17.443: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
233local#307 06:23:17.444: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kvj2xrmm] at 0x0000000002723FD0> won
234local#308 06:23:17.444: told to disconnect
235local#309 06:23:17.444: Stopping factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kvj2xrmm] at 0x0000000002723DA0>
236local#310 06:23:17.444: told to disconnect
237local#311 06:23:17.444: connectorFinished (<foolscap.negotiate.TubConnector object at 0x0000000002723BA8 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to kvj2xrmmti3wp2albm3mmo3ulead5fy2>)
238local#312 06:23:17.444: Stopping factory <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kvj2xrmm] at 0x0000000002723EB8>
239local#313 06:23:17.444: connectorFinished (<foolscap.negotiate.TubConnector object at 0x0000000002723BA8 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to kvj2xrmmti3wp2albm3mmo3ulead5fy2>)
240local#314 06:23:17.448: got connection to inxoy6ui, getting versions
241local#315 06:23:17.463: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: 8703d6eb24bbf81a 5\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
242local#316 06:23:17.463: handleDECIDING(isClient=True): banana-decision-version: 3
243current-connection: 8703d6eb24bbf81a 5
244initial-vocab-table-index: 1 bb33
245local#317 06:23:17.463: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': '8703d6eb24bbf81a 5'}
246local#318 06:23:17.463: Negotiate.switchToBanana(isClient=True)
247local#319 06:23:17.463: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
248local#320 06:23:17.463: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to kqyu52yz] at 0x000000000272A8D0> won
249local#321 06:23:17.463: connectorFinished (<foolscap.negotiate.TubConnector object at 0x000000000272A860 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to kqyu52yzkipbt5ktyu6x56s6isi2khyc>)
250local#322 06:23:17.509: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: e02e66597cd725d7 4\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
251local#323 06:23:17.509: handleDECIDING(isClient=True): banana-decision-version: 3
252current-connection: e02e66597cd725d7 4
253initial-vocab-table-index: 1 bb33
254local#324 06:23:17.509: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': 'e02e66597cd725d7 4'}
255local#325 06:23:17.509: Negotiate.switchToBanana(isClient=True)
256local#326 06:23:17.509: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
257local#327 06:23:17.509: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to pmitrhwg] at 0x0000000002723400> won
258local#328 06:23:17.509: connectorFinished (<foolscap.negotiate.TubConnector object at 0x0000000002723390 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to pmitrhwg7hminstxvijbyzefsovwq7hf>)
259local#329 06:23:17.517: got connection to kvj2xrmm, getting versions
260local#330 06:23:17.528: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: 7807f4a8f5d836a4 3\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
261local#331 06:23:17.528: handleDECIDING(isClient=True): banana-decision-version: 3
262current-connection: 7807f4a8f5d836a4 3
263initial-vocab-table-index: 1 bb33
264local#332 06:23:17.528: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': '7807f4a8f5d836a4 3'}
265local#333 06:23:17.528: Negotiate.switchToBanana(isClient=True)
266local#334 06:23:17.528: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
267local#335 06:23:17.528: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to baeq4skx] at 0x00000000027239E8> won
268local#336 06:23:17.528: connectorFinished (<foolscap.negotiate.TubConnector object at 0x0000000002723978 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to baeq4skxppta2cc6wnjfv7k2uu7ms4b6>)
269local#337 06:23:17.529: got connection to kqyu52yz, getting versions
270local#338 06:23:17.532: Negotiation started
271local#339 06:23:17.532: initClient: to target pb://qivwuhf6cnon45sld7lq5a3iugsjjqmw
272local#340 06:23:17.532: sendPlaintextClient: GET for tubID qivwuhf6cnon45sld7lq5a3iugsjjqmw
273local#341 06:23:17.532: sendPlaintextClient: wantEncryption=True
274local#342 06:23:17.585: SharemapUpdater(wtje5): starting (MODE_CHECK)
275local#347 06:23:17.595: storage: slot_readv wtje5rcqexjsmyff5tysmjg66u []
276local#348 06:23:17.595: returning shares [2, 3]
277local#349 06:23:17.596: got result from [aty4re3a], 2 shares
278local#352 06:23:17.598:  found valid version 32-es6x from aty4re3a-sh2: 5-12/590/586
279local#354 06:23:17.598:  found valid version 30-gvrh from aty4re3a-sh3: 5-12/590/586
280local#359 06:23:17.605: kvj2xrmm provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 0, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.8.3'}
281local#360 06:23:17.611: kqyu52yz provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 687143179776L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.9.1'}
282local#361 06:23:17.627: inxoy6ui provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 475073891072L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.9.1'}
283local#362 06:23:17.632: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: 93a15c061ffd0b07 2\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
284local#363 06:23:17.632: handleDECIDING(isClient=True): banana-decision-version: 3
285current-connection: 93a15c061ffd0b07 2
286initial-vocab-table-index: 1 bb33
287local#364 06:23:17.632: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': '93a15c061ffd0b07 2'}
288local#365 06:23:17.632: Negotiate.switchToBanana(isClient=True)
289local#366 06:23:17.632: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
290local#367 06:23:17.632: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to g4xvpwqa] at 0x000000000272A470> won
291local#368 06:23:17.632: connectorFinished (<foolscap.negotiate.TubConnector object at 0x000000000272A438 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to g4xvpwqadyiwfu26qfxkgmjjxmony52p>)
292local#369 06:23:17.668: got result from [hpd3hn75], 2 shares
293local#372 06:23:17.668:  found valid version 32-es6x from hpd3hn75-sh3: 5-12/590/586
294local#374 06:23:17.670:  found valid version 31-o7xv from hpd3hn75-sh6: 5-12/590/586
295local#379 06:23:17.703: got connection to pmitrhwg, getting versions
296local#380 06:23:17.726: got result from [huadamis], 1 shares
297local#383 06:23:17.727:  found valid version 31-o7xv from huadamis-sh8: 5-12/590/586
298local#388 06:23:17.730: got connection to baeq4skx, getting versions
299local#389 06:23:17.753: got result from [b55ww7wa], 1 shares
300local#392 06:23:17.753:  found valid version 32-es6x from b55ww7wa-sh10: 5-12/590/586
301local#394 06:23:17.753: all queries are retired, no extra peers: done
302local#395 06:23:17.753: servermap: 1*seq30-gvrh/2*seq31-o7xv/3*seq32-es6x
303local#398 06:23:17.757: SharemapUpdater(wtje5): starting (MODE_READ)
304local#406 06:23:17.763: storage: slot_readv wtje5rcqexjsmyff5tysmjg66u []
305local#407 06:23:17.765: returning shares [2, 3]
306local#408 06:23:17.766: got result from [aty4re3a], 2 shares
307local#411 06:23:17.766:  found valid version 32-es6x from aty4re3a-sh2: 5-12/590/586
308local#413 06:23:17.766:  found valid version 30-gvrh from aty4re3a-sh3: 5-12/590/586
309local#422 06:23:17.792: Negotiation started
310local#423 06:23:17.792: initClient: to target pb://vifimgiwol6shdmyoxyqvet5oz6dqnt5
311local#424 06:23:17.792: sendPlaintextClient: GET for tubID vifimgiwol6shdmyoxyqvet5oz6dqnt5
312local#425 06:23:17.792: sendPlaintextClient: wantEncryption=True
313local#426 06:23:17.823: got result from [hpd3hn75], 2 shares
314local#429 06:23:17.823:  found valid version 32-es6x from hpd3hn75-sh3: 5-12/590/586
315local#431 06:23:17.825:  found valid version 31-o7xv from hpd3hn75-sh6: 5-12/590/586
316local#440 06:23:17.826: got result from [b55ww7wa], 1 shares
317local#443 06:23:17.826:  found valid version 32-es6x from b55ww7wa-sh10: 5-12/590/586
318local#452 06:23:17.838: got result from [huadamis], 1 shares
319local#455 06:23:17.839:  found valid version 31-o7xv from huadamis-sh8: 5-12/590/586
320local#464 06:23:17.842: got result from [kqyu52yz], 2 shares
321local#467 06:23:17.842:  found valid version 29-tdwa from kqyu52yz-sh10: 5-12/590/586
322local#469 06:23:17.842:  found valid version 31-o7xv from kqyu52yz-sh4: 5-12/590/586
323local#478 06:23:17.888: got connection to g4xvpwqa, getting versions
324local#479 06:23:17.914: pmitrhwg provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 856782827520L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.9.1'}
325local#480 06:23:17.937: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: f3d2c7eb02f4e973\r\nmy-tub-id: jbrse33y3gmtpauhhgfsrti4o4mzlcsk\r\n\r\n'
326local#481 06:23:17.937: evaluateHello(isClient=True): offer={'my-tub-id': 'jbrse33y3gmtpauhhgfsrti4o4mzlcsk', 'my-incarnation': 'f3d2c7eb02f4e973', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
327local#482 06:23:17.937: iAmTheMaster: False
328local#483 06:23:17.973: got result from [kvj2xrmm], 1 shares
329local#486 06:23:17.973:  found valid version 32-es6x from kvj2xrmm-sh11: 5-12/590/586
330local#495 06:23:17.974: dataReceived(isClient=True,phase=0,options={}): 'HTTP/1.1 101 Switching Protocols\r\nUpgrade: TLS/1.0, PB/1.0\r\nConnection: Upgrade\r\n\r\n'
331local#496 06:23:17.974: handlePLAINTEXTClient: header='HTTP/1.1 101 Switching Protocols
332Upgrade: TLS/1.0, PB/1.0
333Connection: Upgrade'
334local#497 06:23:17.974: startENCRYPTED(isClient=True, encrypted=True)
335local#498 06:23:17.974: startTLS, client=True
336local#499 06:23:17.974: Negotiate.sendHello (isClient=True): {'my-incarnation': '9a6c03436c11e75e', 'last-connection': 'none 0', 'my-tub-id': 'aty4re3a3ygvb6a2gext5vbcgdzs4ihk', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
337local#500 06:23:18.089: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: bbecd94c5a919a21\r\nmy-tub-id: gbytbnxw2hkbpjslf7mevzejefmdomtb\r\n\r\n'
338local#501 06:23:18.089: evaluateHello(isClient=True): offer={'my-tub-id': 'gbytbnxw2hkbpjslf7mevzejefmdomtb', 'my-incarnation': 'bbecd94c5a919a21', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
339local#502 06:23:18.089: iAmTheMaster: False
340local#503 06:23:18.099: got result from [inxoy6ui], 1 shares
341local#506 06:23:18.099:  found valid version 32-es6x from inxoy6ui-sh8: 5-12/590/586
342local#508 06:23:18.099: all queries are retired, no extra peers: done
343local#509 06:23:18.099: servermap: 1*seq29-tdwa/1*seq30-gvrh/3*seq31-o7xv/5*seq32-es6x
344local#512 06:23:18.101: Retrieve(wtje5): starting
345local#524 06:23:18.101: getting blockhashes for segment 0, share 2: set([0])
346local#525 06:23:18.101: also need sharehashes for share 2: set([18, 4, 2, 7])
347local#526 06:23:18.102: getting blockhashes for segment 0, share 3: set([0])
348local#527 06:23:18.104: also need sharehashes for share 3: set([17, 2, 4, 7])
349local#528 06:23:18.105: getting blockhashes for segment 0, share 8: set([0])
350local#529 06:23:18.105: also need sharehashes for share 8: set([24, 1, 12, 6])
351local#530 06:23:18.105: getting blockhashes for segment 0, share 10: set([0])
352local#531 06:23:18.107: also need sharehashes for share 10: set([1, 26, 11, 6])
353local#532 06:23:18.108: getting blockhashes for segment 0, share 11: set([0])
354local#533 06:23:18.108: also need sharehashes for share 11: set([25, 11, 6, 1])
355local#534 06:23:18.111: storage: slot_readv wtje5rcqexjsmyff5tysmjg66u [2]
356local#535 06:23:18.111: returning shares [2]
357local#536 06:23:18.111: storage: slot_readv wtje5rcqexjsmyff5tysmjg66u [2]
358local#537 06:23:18.112: returning shares [2]
359local#538 06:23:18.114: validating share 2 for segment 0
360local#539 06:23:18.114: the reader gave me the following blockhashes: [0]
361local#540 06:23:18.114: the reader gave me the following sharehashes: [2, 4, 18, 7]
362local#541 06:23:18.114: share 2 is valid for segment 0
363local#542 06:23:18.144: g4xvpwqa provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 290838614016L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.8.3'}
364local#543 06:23:18.173: validating share 3 for segment 0
365local#544 06:23:18.173: the reader gave me the following blockhashes: [0]
366local#545 06:23:18.173: the reader gave me the following sharehashes: [17, 2, 4, 7]
367local#546 06:23:18.173: share 3 is valid for segment 0
368local#547 06:23:18.191: validating share 10 for segment 0
369local#548 06:23:18.191: the reader gave me the following blockhashes: [0]
370local#549 06:23:18.191: the reader gave me the following sharehashes: [1, 26, 11, 6]
371local#550 06:23:18.193: share 10 is valid for segment 0
372local#551 06:23:18.273: validating share 11 for segment 0
373local#552 06:23:18.273: the reader gave me the following blockhashes: [0]
374local#553 06:23:18.273: the reader gave me the following sharehashes: [1, 11, 6, 25]
375local#554 06:23:18.273: share 11 is valid for segment 0
376local#555 06:23:18.326: validating share 8 for segment 0
377local#556 06:23:18.326: the reader gave me the following blockhashes: [0]
378local#557 06:23:18.326: the reader gave me the following sharehashes: [24, 1, 12, 6]
379local#558 06:23:18.326: share 8 is valid for segment 0
380local#559 06:23:18.326: trying to decode and decrypt segment 0
381local#560 06:23:18.326: everything looks ok, building segment 0
382local#561 06:23:18.326: decoding segment 0
383local#562 06:23:18.326: now decoding segment 0 of 1
384local#563 06:23:18.326:  joined length 590, datalength 586
385local#564 06:23:18.326:  segment len=586
386local#565 06:23:18.326: decrypting segment 0
387local#566 06:23:18.328: got plaintext for segment 0
388local#567 06:23:18.328: stripping 0 bytes off of the first segment
389local#568 06:23:18.328: original segment length: 586
390local#569 06:23:18.328: new segment length: 586
391local#570 06:23:18.328: adding 0 new peers to the active list
392local#571 06:23:18.328: got plaintext, done
393local#572 06:23:18.349: SharemapUpdater(yudiz): starting (MODE_CHECK)
394local#582 06:23:18.361: baeq4skx provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 777383396864L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.8.3'}
395local#583 06:23:18.375: storage: slot_readv yudizvvpuewsxzmgtvbiznak3m []
396local#584 06:23:18.375: returning shares [5]
397local#585 06:23:18.377: got result from [aty4re3a], 1 shares
398local#588 06:23:18.378:  found valid version 14-3lsw from aty4re3a-sh5: 5-12/2405/2404
399local#593 06:23:18.381: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: f3d2c7eb02f4e973 4\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
400local#594 06:23:18.381: handleDECIDING(isClient=True): banana-decision-version: 3
401current-connection: f3d2c7eb02f4e973 4
402initial-vocab-table-index: 1 bb33
403local#595 06:23:18.381: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': 'f3d2c7eb02f4e973 4'}
404local#596 06:23:18.381: Negotiate.switchToBanana(isClient=True)
405local#597 06:23:18.381: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
406local#598 06:23:18.381: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to jbrse33y] at 0x0000000002723240> won
407local#599 06:23:18.381: connectorFinished (<foolscap.negotiate.TubConnector object at 0x00000000027230B8 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to jbrse33y3gmtpauhhgfsrti4o4mzlcsk>)
408local#600 06:23:18.424: got result from [hpd3hn75], 2 shares
409local#603 06:23:18.424:  found valid version 12-n34e from hpd3hn75-sh8: 5-12/2405/2404
410local#605 06:23:18.424:  found valid version 14-3lsw from hpd3hn75-sh2: 5-12/2405/2404
411local#610 06:23:18.427: got result from [b55ww7wa], 0 shares
412local#616 06:23:18.451: got result from [kqyu52yz], 2 shares
413local#619 06:23:18.453:  found valid version 8-3p7b from kqyu52yz-sh1: 5-12/1865/1864
414local#621 06:23:18.453:  found valid version 8-3p7b from kqyu52yz-sh11: 5-12/1865/1864
415local#626 06:23:18.555: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: c85e879bdc30dc3f\r\nmy-tub-id: vifimgiwol6shdmyoxyqvet5oz6dqnt5\r\n\r\n'
416local#627 06:23:18.555: evaluateHello(isClient=True): offer={'my-tub-id': 'vifimgiwol6shdmyoxyqvet5oz6dqnt5', 'my-incarnation': 'c85e879bdc30dc3f', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
417local#628 06:23:18.555: iAmTheMaster: False
418local#629 06:23:18.569: got result from [inxoy6ui], 0 shares
419local#635 06:23:18.605: got result from [kvj2xrmm], 1 shares
420local#638 06:23:18.605:  found valid version 14-3lsw from kvj2xrmm-sh7: 5-12/2405/2404
421local#643 06:23:18.605: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: bbecd94c5a919a21 2\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
422local#644 06:23:18.605: handleDECIDING(isClient=True): banana-decision-version: 3
423current-connection: bbecd94c5a919a21 2
424initial-vocab-table-index: 1 bb33
425local#645 06:23:18.605: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': 'bbecd94c5a919a21 2'}
426local#646 06:23:18.605: Negotiate.switchToBanana(isClient=True)
427local#647 06:23:18.605: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
428local#648 06:23:18.605: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to gbytbnxw] at 0x00000000027237F0> won
429local#649 06:23:18.605: connectorFinished (<foolscap.negotiate.TubConnector object at 0x0000000002723780 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to gbytbnxw2hkbpjslf7mevzejefmdomtb>)
430local#650 06:23:18.607: got connection to jbrse33y, getting versions
431local#651 06:23:18.650: got result from [g4xvpwqa], 1 shares
432local#654 06:23:18.651:  found valid version 14-3lsw from g4xvpwqa-sh9: 5-12/2405/2404
433local#659 06:23:18.653: got result from [huadamis], 1 shares
434local#662 06:23:18.653:  found valid version 14-3lsw from huadamis-sh8: 5-12/2405/2404
435local#665 06:23:18.653: _check_for_done, mode is 'MODE_CHECK', 1 queries outstanding, 0 extra peers available, 1 'must query' peers left, need_privkey=False
436local#666 06:23:18.653: 1 'must query' peers left
437local#667 06:23:18.655: dataReceived(isClient=True,phase=0,options={}): 'HTTP/1.1 101 Switching Protocols\r\nUpgrade: TLS/1.0, PB/1.0\r\nConnection: Upgrade\r\n\r\n'
438local#668 06:23:18.655: handlePLAINTEXTClient: header='HTTP/1.1 101 Switching Protocols
439Upgrade: TLS/1.0, PB/1.0
440Connection: Upgrade'
441local#669 06:23:18.655: startENCRYPTED(isClient=True, encrypted=True)
442local#670 06:23:18.655: startTLS, client=True
443local#671 06:23:18.655: Negotiate.sendHello (isClient=True): {'my-incarnation': '9a6c03436c11e75e', 'last-connection': 'none 0', 'my-tub-id': 'aty4re3a3ygvb6a2gext5vbcgdzs4ihk', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
444local#672 06:23:18.822: jbrse33y provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'maximum-immutable-share-size': 217038468608L, 'tolerates-immutable-read-overrun': True, 'delete-mutable-shares-with-zero-length-writev': True}, 'application-version': 'allmydata-tahoe/1.8.2'}
445local#673 06:23:18.865: got result from [pmitrhwg], 1 shares
446local#674 06:23:18.865: _got_results done
447local#675 06:23:18.865: _got_results: got shnum #4 from peerid pmitrhwg
448local#676 06:23:18.865:  found valid version 14-3lsw from pmitrhwg-sh4: 5-12/2405/2404
449local#677 06:23:18.865: _check_for_done, mode is 'MODE_CHECK', 0 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
450local#678 06:23:18.865: all queries are retired, no extra peers: done
451local#679 06:23:18.865: servermap: 1*seq12-n34e/6*seq14-3lsw/2*seq8-3p7b
452local#680 06:23:18.865: _check_for_done, mode is 'MODE_CHECK', 0 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
453local#681 06:23:18.865: but we're not running
454local#682 06:23:18.868: SharemapUpdater(yudiz): starting (MODE_READ)
455local#683 06:23:18.868: sending query to [hpd3hn75], readsize=4000
456local#684 06:23:18.868: sending query to [huadamis], readsize=4000
457local#685 06:23:18.868: sending query to [baeq4skx], readsize=4000
458local#686 06:23:18.869: sending query to [kvj2xrmm], readsize=4000
459local#687 06:23:18.869: sending query to [b55ww7wa], readsize=4000
460local#688 06:23:18.871: sending query to [inxoy6ui], readsize=4000
461local#689 06:23:18.871: sending query to [kqyu52yz], readsize=4000
462local#690 06:23:18.871: sending query to [aty4re3a], readsize=4000
463local#691 06:23:18.874: storage: slot_readv yudizvvpuewsxzmgtvbiznak3m []
464local#692 06:23:18.875: returning shares [5]
465local#693 06:23:18.875: got result from [aty4re3a], 1 shares
466local#694 06:23:18.877: _got_results done
467local#695 06:23:18.877: _got_results: got shnum #5 from peerid aty4re3a
468local#696 06:23:18.877:  found valid version 14-3lsw from aty4re3a-sh5: 5-12/2405/2404
469local#697 06:23:18.877: _check_for_done, mode is 'MODE_READ', 7 queries outstanding, 3 extra peers available, 0 'must query' peers left, need_privkey=False
470local#698 06:23:18.877: 1 completed, 8 to query: need more
471local#699 06:23:18.877:  there are 7 queries outstanding
472local#700 06:23:18.877: sending 0 more queries:
473local#701 06:23:18.877: _check_for_done, mode is 'MODE_READ', 7 queries outstanding, 3 extra peers available, 0 'must query' peers left, need_privkey=False
474local#702 06:23:18.877: 1 completed, 8 to query: need more
475local#703 06:23:18.877:  there are 7 queries outstanding
476local#704 06:23:18.877: sending 0 more queries:
477local#705 06:23:18.924: got connection to gbytbnxw, getting versions
478local#706 06:23:18.934: got result from [hpd3hn75], 2 shares
479local#707 06:23:18.934: _got_results done
480local#708 06:23:18.934: _got_results: got shnum #8 from peerid hpd3hn75
481local#709 06:23:18.934:  found valid version 12-n34e from hpd3hn75-sh8: 5-12/2405/2404
482local#710 06:23:18.934: _got_results: got shnum #2 from peerid hpd3hn75
483local#711 06:23:18.934:  found valid version 14-3lsw from hpd3hn75-sh2: 5-12/2405/2404
484local#712 06:23:18.934: _check_for_done, mode is 'MODE_READ', 6 queries outstanding, 3 extra peers available, 0 'must query' peers left, need_privkey=False
485local#713 06:23:18.934: 2 completed, 8 to query: need more
486local#714 06:23:18.934:  there are 6 queries outstanding
487local#715 06:23:18.934: sending 0 more queries:
488local#716 06:23:18.934: _check_for_done, mode is 'MODE_READ', 6 queries outstanding, 3 extra peers available, 0 'must query' peers left, need_privkey=False
489local#717 06:23:18.934: 2 completed, 8 to query: need more
490local#718 06:23:18.934:  there are 6 queries outstanding
491local#719 06:23:18.934: sending 0 more queries:
492local#720 06:23:18.937: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: c85e879bdc30dc3f 2\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
493local#721 06:23:18.937: handleDECIDING(isClient=True): banana-decision-version: 3
494current-connection: c85e879bdc30dc3f 2
495initial-vocab-table-index: 1 bb33
496local#722 06:23:18.937: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': 'c85e879bdc30dc3f 2'}
497local#723 06:23:18.937: Negotiate.switchToBanana(isClient=True)
498local#724 06:23:18.937: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
499local#725 06:23:18.937: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to vifimgiw] at 0x000000000272A2E8> won
500local#726 06:23:18.937: connectorFinished (<foolscap.negotiate.TubConnector object at 0x000000000272A2B0 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to vifimgiwol6shdmyoxyqvet5oz6dqnt5>)
501local#727 06:23:18.941: got result from [b55ww7wa], 0 shares
502local#728 06:23:18.941: _check_for_done, mode is 'MODE_READ', 5 queries outstanding, 3 extra peers available, 0 'must query' peers left, need_privkey=False
503local#729 06:23:18.941: 3 completed, 8 to query: need more
504local#730 06:23:18.941:  there are 5 queries outstanding
505local#731 06:23:18.943: sending 0 more queries:
506local#732 06:23:18.943: _got_results done
507local#733 06:23:18.943: _check_for_done, mode is 'MODE_READ', 5 queries outstanding, 3 extra peers available, 0 'must query' peers left, need_privkey=False
508local#734 06:23:18.943: 3 completed, 8 to query: need more
509local#735 06:23:18.943:  there are 5 queries outstanding
510local#736 06:23:18.943: sending 0 more queries:
511local#737 06:23:18.963: got result from [huadamis], 1 shares
512local#738 06:23:18.964: _got_results done
513local#739 06:23:18.964: _got_results: got shnum #8 from peerid huadamis
514local#740 06:23:18.964:  found valid version 14-3lsw from huadamis-sh8: 5-12/2405/2404
515local#741 06:23:18.964: _check_for_done, mode is 'MODE_READ', 4 queries outstanding, 3 extra peers available, 0 'must query' peers left, need_privkey=False
516local#742 06:23:18.964: 4 completed, 8 to query: need more
517local#743 06:23:18.964:  there are 4 queries outstanding
518local#744 06:23:18.964:  there are 4 queries outstanding
519local#745 06:23:18.964: sending 1 more queries: [g4xvpwqa]
520local#746 06:23:18.964: sending query to [g4xvpwqa], readsize=4000
521local#747 06:23:18.966: _check_for_done, mode is 'MODE_READ', 5 queries outstanding, 2 extra peers available, 0 'must query' peers left, need_privkey=False
522local#748 06:23:18.966: 4 completed, 8 to query: need more
523local#749 06:23:18.966:  there are 5 queries outstanding
524local#750 06:23:18.966: sending 0 more queries:
525local#751 06:23:19.017: got result from [kqyu52yz], 2 shares
526local#752 06:23:19.019: _got_results done
527local#753 06:23:19.019: _got_results: got shnum #1 from peerid kqyu52yz
528local#754 06:23:19.019:  found valid version 8-3p7b from kqyu52yz-sh1: 5-12/1865/1864
529local#755 06:23:19.019: _got_results: got shnum #11 from peerid kqyu52yz
530local#756 06:23:19.019:  found valid version 8-3p7b from kqyu52yz-sh11: 5-12/1865/1864
531local#757 06:23:19.019: _check_for_done, mode is 'MODE_READ', 4 queries outstanding, 2 extra peers available, 0 'must query' peers left, need_privkey=False
532local#758 06:23:19.019: 5 completed, 8 to query: need more
533local#759 06:23:19.019:  there are 4 queries outstanding
534local#760 06:23:19.019:  there are 4 queries outstanding
535local#761 06:23:19.019: sending 1 more queries: [jbrse33y]
536local#762 06:23:19.019: sending query to [jbrse33y], readsize=4000
537local#763 06:23:19.019: _check_for_done, mode is 'MODE_READ', 5 queries outstanding, 1 extra peers available, 0 'must query' peers left, need_privkey=False
538local#764 06:23:19.020: 5 completed, 8 to query: need more
539local#765 06:23:19.020:  there are 5 queries outstanding
540local#766 06:23:19.020: sending 0 more queries:
541local#767 06:23:19.046: got result from [kvj2xrmm], 1 shares
542local#768 06:23:19.048: _got_results done
543local#769 06:23:19.048: _got_results: got shnum #7 from peerid kvj2xrmm
544local#770 06:23:19.048:  found valid version 14-3lsw from kvj2xrmm-sh7: 5-12/2405/2404
545local#771 06:23:19.048: _check_for_done, mode is 'MODE_READ', 4 queries outstanding, 1 extra peers available, 0 'must query' peers left, need_privkey=False
546local#772 06:23:19.048: 6 completed, 8 to query: need more
547local#773 06:23:19.048:  there are 4 queries outstanding
548local#774 06:23:19.048:  there are 4 queries outstanding
549local#775 06:23:19.048: sending 1 more queries: [pmitrhwg]
550local#776 06:23:19.048: sending query to [pmitrhwg], readsize=4000
551local#777 06:23:19.049: _check_for_done, mode is 'MODE_READ', 5 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
552local#778 06:23:19.049: 6 completed, 8 to query: need more
553local#779 06:23:19.049:  there are 5 queries outstanding
554local#780 06:23:19.049: sending 0 more queries:
555local#781 06:23:19.055: got result from [inxoy6ui], 0 shares
556local#782 06:23:19.055: _check_for_done, mode is 'MODE_READ', 4 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
557local#783 06:23:19.055: 7 completed, 8 to query: need more
558local#784 06:23:19.055:  there are 4 queries outstanding
559local#785 06:23:19.055: sending 0 more queries:
560local#786 06:23:19.055: _got_results done
561local#787 06:23:19.055: _check_for_done, mode is 'MODE_READ', 4 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
562local#788 06:23:19.055: 7 completed, 8 to query: need more
563local#789 06:23:19.055:  there are 4 queries outstanding
564local#790 06:23:19.055: sending 0 more queries:
565local#791 06:23:19.114: got result from [baeq4skx], 1 shares
566local#792 06:23:19.114: _got_results done
567local#793 06:23:19.114: _got_results: got shnum #6 from peerid baeq4skx
568local#794 06:23:19.114:  found valid version 14-3lsw from baeq4skx-sh6: 5-12/2405/2404
569local#795 06:23:19.114: _check_for_done, mode is 'MODE_READ', 3 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
570local#796 06:23:19.114: no higher-seqnum: done
571local#797 06:23:19.114: servermap: 1*seq12-n34e/5*seq14-3lsw/2*seq8-3p7b
572local#798 06:23:19.115: _check_for_done, mode is 'MODE_READ', 3 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
573local#799 06:23:19.115: but we're not running
574local#800 06:23:19.115: Retrieve(yudiz): starting
575local#801 06:23:19.115: got seqnum 14
576local#802 06:23:19.115: got encoding parameters: k: 5 n: 12 1 segments of 2405 bytes each (2405 byte tail segment)
577local#803 06:23:19.115: starting download
578local#804 06:23:19.115: adding 5 new peers to the active list
579local#805 06:23:19.115: added reader for share 2
580local#806 06:23:19.115: added reader for share 5
581local#807 06:23:19.117: added reader for share 6
582local#808 06:23:19.117: added reader for share 7
583local#809 06:23:19.118: added reader for share 8
584local#810 06:23:19.118: on segment 1 of 1
585local#811 06:23:19.118: processing segment 0
586local#812 06:23:19.118: getting blockhashes for segment 0, share 2: set([0])
587local#813 06:23:19.119: also need sharehashes for share 2: set([18, 4, 2, 7])
588local#814 06:23:19.121: getting blockhashes for segment 0, share 5: set([0])
589local#815 06:23:19.121: also need sharehashes for share 5: set([19, 10, 3, 2])
590local#816 06:23:19.122: getting blockhashes for segment 0, share 6: set([0])
591local#817 06:23:19.124: also need sharehashes for share 6: set([9, 2, 3, 22])
592local#818 06:23:19.125: getting blockhashes for segment 0, share 7: set([0])
593local#819 06:23:19.125: also need sharehashes for share 7: set([9, 2, 3, 21])
594local#820 06:23:19.128: getting blockhashes for segment 0, share 8: set([0])
595local#821 06:23:19.128: also need sharehashes for share 8: set([24, 1, 12, 6])
596local#822 06:23:19.132: storage: slot_readv yudizvvpuewsxzmgtvbiznak3m [5]
597local#823 06:23:19.132: returning shares [5]
598local#824 06:23:19.134: storage: slot_readv yudizvvpuewsxzmgtvbiznak3m [5]
599local#825 06:23:19.134: returning shares [5]
600local#826 06:23:19.134: storage: slot_readv yudizvvpuewsxzmgtvbiznak3m [5]
601local#827 06:23:19.134: returning shares [5]
602local#828 06:23:19.134: storage: slot_readv yudizvvpuewsxzmgtvbiznak3m [5]
603local#829 06:23:19.135: returning shares [5]
604local#830 06:23:19.135: got connection to vifimgiw, getting versions
605local#831 06:23:19.137: got valid privkey from shnum 5 on reader <allmydata.mutable.layout.MDMFSlotReadProxy instance at 0x0000000004B96AC8>
606local#832 06:23:19.138: validating share 5 for segment 0
607local#833 06:23:19.138: the reader gave me the following blockhashes: [0]
608local#834 06:23:19.138: the reader gave me the following sharehashes: [19, 2, 3, 10]
609local#835 06:23:19.138: share 5 is valid for segment 0
610local#836 06:23:19.197: got valid privkey from shnum 2 on reader <allmydata.mutable.layout.MDMFSlotReadProxy instance at 0x0000000004B96A88>
611local#837 06:23:19.197: validating share 2 for segment 0
612local#838 06:23:19.197: the reader gave me the following blockhashes: [0]
613local#839 06:23:19.197: the reader gave me the following sharehashes: [2, 4, 18, 7]
614local#840 06:23:19.198: share 2 is valid for segment 0
615local#841 06:23:19.240: got result from [g4xvpwqa], 1 shares
616local#842 06:23:19.240: but we're not running, so we'll ignore it
617local#843 06:23:19.240: _check_for_done, mode is 'MODE_READ', 2 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
618local#844 06:23:19.240: but we're not running
619local#845 06:23:19.263: got valid privkey from shnum 7 on reader <allmydata.mutable.layout.MDMFSlotReadProxy instance at 0x0000000004B96A08>
620local#846 06:23:19.263: validating share 7 for segment 0
621local#847 06:23:19.263: the reader gave me the following blockhashes: [0]
622local#848 06:23:19.263: the reader gave me the following sharehashes: [9, 2, 3, 21]
623local#849 06:23:19.263: share 7 is valid for segment 0
624local#850 06:23:19.339: got valid privkey from shnum 8 on reader <allmydata.mutable.layout.MDMFSlotReadProxy instance at 0x0000000004B969C8>
625local#851 06:23:19.341: validating share 8 for segment 0
626local#852 06:23:19.341: the reader gave me the following blockhashes: [0]
627local#853 06:23:19.341: the reader gave me the following sharehashes: [24, 1, 12, 6]
628local#854 06:23:19.341: share 8 is valid for segment 0
629local#855 06:23:19.342: vifimgiw provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 981054612992L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.8.3'}
630local#856 06:23:19.345: got valid privkey from shnum 6 on reader <allmydata.mutable.layout.MDMFSlotReadProxy instance at 0x0000000004B96A48>
631local#857 06:23:19.345: validating share 6 for segment 0
632local#858 06:23:19.345: the reader gave me the following blockhashes: [0]
633local#859 06:23:19.345: the reader gave me the following sharehashes: [9, 2, 3, 22]
634local#860 06:23:19.345: share 6 is valid for segment 0
635local#861 06:23:19.345: trying to decode and decrypt segment 0
636local#862 06:23:19.345: everything looks ok, building segment 0
637local#863 06:23:19.345: decoding segment 0
638local#864 06:23:19.345: now decoding segment 0 of 1
639local#865 06:23:19.345:  joined length 2405, datalength 2404
640local#866 06:23:19.345:  segment len=2404
641local#867 06:23:19.345: decrypting segment 0
642local#868 06:23:19.345: got plaintext for segment 0
643local#869 06:23:19.345: stripping 0 bytes off of the first segment
644local#870 06:23:19.345: original segment length: 2404
645local#871 06:23:19.345: new segment length: 2404
646local#872 06:23:19.345: adding 0 new peers to the active list
647local#873 06:23:19.345: got plaintext, done
648local#874 06:23:19.346: Publish(yudiz): starting
649local#875 06:23:19.346: starting publish, datalen is 2404
650local#876 06:23:19.346: new seqnum will be 15
651local#877 06:23:19.346: building encoding parameters for file
652local#878 06:23:19.346: got segsize 2405
653local#879 06:23:19.346: got 1 segments
654local#880 06:23:19.346: got tail segment size 2404
655local#881 06:23:19.346: got start segment 0
656local#882 06:23:19.346: got end segment 0
657local#883 06:23:19.346: current goal: before update: , sh1 to [kqyu52yz], sh2 to [hpd3hn75], sh4 to [pmitrhwg], sh5 to [aty4re3a], sh7 to [kvj2xrmm], sh8 to [hpd3hn75], sh8 to [huadamis], sh9 to [g4xvpwqa], sh11 to [kqyu52yz]
658local#884 06:23:19.346: we are planning to push new seqnum=#15
659local#885 06:23:19.348: current goal: after update: , sh0 to [inxoy6ui], sh1 to [kqyu52yz], sh2 to [hpd3hn75], sh3 to [b55ww7wa], sh4 to [pmitrhwg], sh5 to [aty4re3a], sh6 to [baeq4skx], sh7 to [kvj2xrmm], sh8 to [hpd3hn75], sh8 to [huadamis], sh9 to [g4xvpwqa], sh10 to [jbrse33y], sh11 to [kqyu52yz]
660local#886 06:23:19.348: we are planning to push new seqnum=#15
661local#887 06:23:19.348: Starting push
662local#888 06:23:19.348: Pushing segment 1 of 1
663local#889 06:23:19.375: storage: slot_writev yudizvvpuewsxzmgtvbiznak3m
664local#890 06:23:19.378: _got_write_answer from aty4re3a, share 5
665local#891 06:23:19.380: found the following surprise shares: set([])
666local#892 06:23:19.380: wrote successfully: adding new share to servermap
667local#893 06:23:19.403: got result from [jbrse33y], 1 shares
668local#894 06:23:19.403: but we're not running, so we'll ignore it
669local#895 06:23:19.403: _check_for_done, mode is 'MODE_READ', 1 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
670local#896 06:23:19.403: but we're not running
671local#897 06:23:19.403: dataReceived(isClient=True,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nmy-incarnation: 4bd27a164f4d2704\r\nmy-tub-id: qivwuhf6cnon45sld7lq5a3iugsjjqmw\r\n\r\n'
672local#898 06:23:19.403: evaluateHello(isClient=True): offer={'my-tub-id': 'qivwuhf6cnon45sld7lq5a3iugsjjqmw', 'my-incarnation': '4bd27a164f4d2704', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
673local#899 06:23:19.403: iAmTheMaster: False
674local#900 06:23:19.453: _got_write_answer from hpd3hn75, share 2
675local#901 06:23:19.453: found the following surprise shares: set([8])
676local#902 06:23:19.453: they had shares [8] that we didn't know about [INCIDENT-TRIGGER]
677local#903 06:23:19.612: wrote successfully: adding new share to servermap
678local#904 06:23:19.614: _got_write_answer from kvj2xrmm, share 7
679local#905 06:23:19.614: found the following surprise shares: set([])
680local#906 06:23:19.615: wrote successfully: adding new share to servermap
681local#907 06:23:19.615: _got_write_answer from jbrse33y, share 10
682local#908 06:23:19.615: found the following surprise shares: set([])
683local#909 06:23:19.615: our testv failed, so the write did not happen
684local#910 06:23:19.615: _got_write_answer from baeq4skx, share 6
685local#911 06:23:19.615: found the following surprise shares: set([])
686local#912 06:23:19.615: our testv failed, so the write did not happen
687local#913 06:23:19.617: _got_write_answer from kqyu52yz, share 1
688local#914 06:23:19.617: found the following surprise shares: set([])
689local#915 06:23:19.617: wrote successfully: adding new share to servermap
690local#916 06:23:19.617: _got_write_answer from kqyu52yz, share 11
691local#917 06:23:19.617: found the following surprise shares: set([])
692local#918 06:23:19.617: wrote successfully: adding new share to servermap
693local#919 06:23:19.618: _got_write_answer from b55ww7wa, share 3
694local#920 06:23:19.618: found the following surprise shares: set([])
695local#921 06:23:19.618: wrote successfully: adding new share to servermap
696local#922 06:23:19.618: _got_write_answer from huadamis, share 8
697local#923 06:23:19.618: found the following surprise shares: set([])
698local#924 06:23:19.618: wrote successfully: adding new share to servermap
699local#925 06:23:19.674: _got_write_answer from g4xvpwqa, share 9
700local#926 06:23:19.674: found the following surprise shares: set([])
701local#927 06:23:19.674: wrote successfully: adding new share to servermap
702local#928 06:23:19.680: _got_write_answer from inxoy6ui, share 0
703local#929 06:23:19.680: found the following surprise shares: set([])
704local#930 06:23:19.680: wrote successfully: adding new share to servermap
705local#931 06:23:19.855: dataReceived(isClient=True,phase=2,options={}): 'banana-decision-version: 3\r\ncurrent-connection: 4bd27a164f4d2704 4\r\ninitial-vocab-table-index: 1 bb33\r\n\r\n'
706local#932 06:23:19.855: handleDECIDING(isClient=True): banana-decision-version: 3
707current-connection: 4bd27a164f4d2704 4
708initial-vocab-table-index: 1 bb33
709local#933 06:23:19.855: Banana.acceptDecision: got {'banana-decision-version': '3', 'initial-vocab-table-index': '1 bb33', 'current-connection': '4bd27a164f4d2704 4'}
710local#934 06:23:19.855: Negotiate.switchToBanana(isClient=True)
711local#935 06:23:19.855: params: {'banana-decision-version': 3, 'initial-vocab-table-index': 1}
712local#936 06:23:19.857: negotiationComplete, <foolscap.negotiate.TubConnectorClientFactory object [from aty4re3a] [to qivwuhf6] at 0x000000000272A6D8> won
713local#937 06:23:19.857: connectorFinished (<foolscap.negotiate.TubConnector object at 0x000000000272A668 from aty4re3a3ygvb6a2gext5vbcgdzs4ihk to qivwuhf6cnon45sld7lq5a3iugsjjqmw>)
714local#938 06:23:19.931: gbytbnxw provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 294346153984L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.7.1'}
715local#939 06:23:20.088: got connection to qivwuhf6, getting versions
716local#940 06:23:20.206: got result from [pmitrhwg], 1 shares
717local#941 06:23:20.206: but we're not running, so we'll ignore it
718local#942 06:23:20.206: _check_for_done, mode is 'MODE_READ', 0 queries outstanding, 0 extra peers available, 0 'must query' peers left, need_privkey=False
719local#943 06:23:20.206: but we're not running
720local#944 06:23:20.328: qivwuhf6 provided version info {'http://allmydata.org/tahoe/protocols/storage/v1': {'delete-mutable-shares-with-zero-length-writev': True, 'maximum-immutable-share-size': 901918483968L, 'fills-holes-with-zero-bytes': True, 'tolerates-immutable-read-overrun': True, 'prevents-read-past-end-of-share-data': True}, 'application-version': 'allmydata-tahoe/1.8.3'}
721local#945 06:23:20.391: _got_write_answer from pmitrhwg, share 4
722local#946 06:23:20.391: found the following surprise shares: set([])
723local#947 06:23:20.391: wrote successfully: adding new share to servermap
724local#948 06:23:20.391: Publish failed with UncoordinatedWriteError
725local#949 06:23:20.392: web: 127.0.0.1 POST /uri/[CENSORED]..?t=stream-deep-check&repair=true&add-lease=true 200 2703
726local#950 06:23:21.713: None
727local#951 06:23:21.808: web: 127.0.0.1 GET / 200 13292