cloud backend: download from S4 hangs on a particular file

[daira]

Rafal Jedruszek reported this problem with S4.

I cannot download one of my files. Just nothing is happening on download trial. Status screen shows 0.0% progress and "fetching segment 0".

Logs are:

starting..
Connecting..
Connected (to pid 915)
Remote Versions:
Nevow: 0.11.1
Twisted: 14.0.2
allmydata-tahoe: 1.10.0
foolscap: 0.6.5
mock: 1.0.1
platform: Linux-debian_8.0-x86_64-64bit_ELF
pyOpenSSL: 0.14
pyasn1: 0.1.7
pycrypto: 2.6.1
pycryptopp: 0.6.0.1206569328141510525648634803928199668821045408958
python: 2.7.8
setuptools: 5.5.1
simplejson: 3.6.5
twisted: 14.0.2
zfec: 1.4.5
zope.interface: unknown
23:43:38.715 L20 []#1704 Immutable.DownloadNode(vukxrvahqlwk) created: size=4400830, guessed_segsize=131072, guessed_numsegs=34
23:43:38.715 L10 []#1705 ShareFinder[si=vukxrvahqlwk] starting
23:43:38.715 L20 []#1706 imm Node(vukxrvah).read(0, 4400830)
23:43:38.715 L10 []#1707 _fetch_next(offset=0) probably wants segnum=0
23:43:38.715 L20 []#1708 imm Node(vukxrvah).get_segment(0)
23:43:38.715 L10 []#1709 ImmutableDownloadNode(vukxrvahqlwk)._start_new_segment: segnum=0
23:43:38.728 L10 []#1710 ShareFinder[si=vukxrvahqlwk] hungry
23:43:38.731 L10 []#1711 ShareFinder loop: running=True hungry=True, pending=
23:43:38.731 L10 []#1712 sending DYHB to [e7ph56p4]
23:43:38.736 L10 []#1713 ShareFinder loop: running=True hungry=True, pending=e7ph56p4
23:43:48.732 L10 []#1714 ShareFinder loop: running=True hungry=True, pending=e7ph56p4

And it stays this way.

On upload try also - nothing is happening. Web page shows "hash: 100.0%, ciphertext: 0.0%, encode: 0.0%", "Status: Contacting Servers [e7ph56p4] (first query), 0 shares left..".

Logs:

23:50:06.576 L20 []#2917 SharemapUpdater(ootig): starting (MODE_READ)
23:50:06.576 L10 []#2918 sending query to [e7ph56p4], readsize=4000
23:50:06.867 L20 []#2919 got result from [e7ph56p4], 1 shares
23:50:06.867 L10 []#2920 _got_results done
23:50:06.871 L10 []#2921 _got_results: got shnum #0 from serverid e7ph56p4
23:50:06.871 L20 []#2922 found valid version 6-uif6 from e7ph56p4-sh0: 1-1/325/325
23:50:06.871 L10 []#2923 _check_for_done, mode is 'MODE_READ', 0 queries outstanding, 0 extra servers available, 0 'must query' servers left, need_privkey=False
23:50:06.871 L20 []#2924 all queries are retired, no extra servers: done
23:50:06.871 L20 []#2925 servermap: 1*seq6-uif6
23:50:06.871 L10 []#2926 _check_for_done, mode is 'MODE_READ', 0 queries outstanding, 0 extra servers available, 0 'must query' servers left, need_privkey=False
23:50:06.871 L10 []#2927 but we're not running
23:50:06.884 L20 []#2928 Retrieve(ootig): starting
23:50:06.884 L20 []#2929 got seqnum 6
23:50:06.885 L20 []#2930 got encoding parameters: k: 1 n: 1 1 segments of 325 bytes each (325 byte tail segment)
23:50:06.885 L20 []#2931 starting download
23:50:06.891 L20 []#2932 adding 1 new servers to the active list
23:50:06.891 L20 []#2933 added reader for share 0
23:50:06.891 L20 []#2934 on segment 1 of 1
23:50:06.891 L20 []#2935 processing segment 0
23:50:06.891 L20 []#2936 getting blockhashes for segment 0, share 0: set([0])
23:50:06.891 L20 []#2937 validating share 0 for segment 0
23:50:06.891 L20 []#2938 the reader gave me the following blockhashes: [0]
23:50:06.891 L20 []#2939 the reader gave me the following sharehashes: []
23:50:06.891 L20 []#2940 share 0 is valid for segment 0
23:50:06.891 L20 []#2941 trying to decode and decrypt segment 0
23:50:06.891 L20 []#2942 everything looks ok, building segment 0
23:50:06.891 L20 []#2943 decoding segment 0
23:50:06.892 L10 []#2944 now decoding segment 0 of 1
23:50:06.892 L20 []#2945 joined length 325, datalength 325
23:50:06.892 L20 []#2946 segment len=325
23:50:06.892 L20 []#2947 decrypting segment 0
23:50:06.892 L20 []#2948 got plaintext for segment 0
23:50:06.892 L20 []#2949 stripping 0 bytes off of the first segment
23:50:06.892 L20 []#2950 original segment length: 325
23:50:06.892 L20 []#2951 new segment length: 325
23:50:06.892 L20 []#2952 adding 0 new servers to the active list
23:50:06.892 L20 []#2953 got plaintext, done
23:50:06.893 L20 []#2954 web: 192.168.1.32 GET /uri/[CENSORED]..?t=json 404 22
23:50:07.038 L20 []#2955 SharemapUpdater(ootig): starting (MODE_READ)
23:50:07.039 L10 []#2956 sending query to [e7ph56p4], readsize=4000
23:50:07.363 L20 []#2957 got result from [e7ph56p4], 1 shares
23:50:07.364 L10 []#2958 _got_results done
23:50:07.367 L10 []#2959 _got_results: got shnum #0 from serverid e7ph56p4
23:50:07.367 L20 []#2960 found valid version 6-uif6 from e7ph56p4-sh0: 1-1/325/325
23:50:07.367 L10 []#2961 _check_for_done, mode is 'MODE_READ', 0 queries outstanding, 0 extra servers available, 0 'must query' servers left, need_privkey=False
23:50:07.367 L20 []#2962 all queries are retired, no extra servers: done
23:50:07.368 L20 []#2963 servermap: 1*seq6-uif6
23:50:07.368 L10 []#2964 _check_for_done, mode is 'MODE_READ', 0 queries outstanding, 0 extra servers available, 0 'must query' servers left, need_privkey=False
23:50:07.368 L10 []#2965 but we're not running
23:50:07.383 L20 []#2966 Retrieve(ootig): starting
23:50:07.383 L20 []#2967 got seqnum 6
23:50:07.383 L20 []#2968 got encoding parameters: k: 1 n: 1 1 segments of 325 bytes each (325 byte tail segment)
23:50:07.383 L20 []#2969 starting download
23:50:07.390 L20 []#2970 adding 1 new servers to the active list
23:50:07.390 L20 []#2971 added reader for share 0
23:50:07.390 L20 []#2972 on segment 1 of 1
23:50:07.390 L20 []#2973 processing segment 0
23:50:07.390 L20 []#2974 getting blockhashes for segment 0, share 0: set([0])
23:50:07.390 L20 []#2975 validating share 0 for segment 0
23:50:07.390 L20 []#2976 the reader gave me the following blockhashes: [0]
23:50:07.390 L20 []#2977 the reader gave me the following sharehashes: []
23:50:07.390 L20 []#2978 share 0 is valid for segment 0
23:50:07.390 L20 []#2979 trying to decode and decrypt segment 0
23:50:07.390 L20 []#2980 everything looks ok, building segment 0
23:50:07.390 L20 []#2981 decoding segment 0
23:50:07.390 L10 []#2982 now decoding segment 0 of 1
23:50:07.390 L20 []#2983 joined length 325, datalength 325
23:50:07.390 L20 []#2984 segment len=325
23:50:07.390 L20 []#2985 decrypting segment 0
23:50:07.390 L20 []#2986 got plaintext for segment 0
23:50:07.390 L20 []#2987 stripping 0 bytes off of the first segment
23:50:07.390 L20 []#2988 original segment length: 325
23:50:07.390 L20 []#2989 new segment length: 325
23:50:07.390 L20 []#2990 adding 0 new servers to the active list
23:50:07.390 L20 []#2991 got plaintext, done
23:50:07.391 L20 []#2992 CHKUploader starting
23:50:07.391 L20 []#2993 starting upload of <allmydata.immutable.upload.EncryptAnUploadable instance at 0x7f72609fb878>
23:50:07.392 L20 []#2994 creating Encoder <Encoder for unknown storage index>
23:50:07.392 L20 []#2995 file size: 4400830
23:50:07.392 L10 []#2996 my encoding parameters: (1, 1, 1, 131072)
23:50:07.392 L20 []#2997 got encoding parameters: 1/1/1 131072
23:50:07.392 L20 []#2998 now setting up codec
23:50:07.416 L20 []#2999 using storage index vukxr
23:50:07.416 L20 []#3000 <Tahoe2ServerSelector for upload vukxr>(vukxr): starting
23:51:46.766 L20 []#3001 None
23:51:46.767 L20 []#3002 web: 192.168.1.9 GET /status/up-1 200 732

(last two lines must be about me downloading status webpage)

I tried with other file and both download and upload works. I noticed it during backup - tahoe was not able to do a backup. I identified that one file is problematic and tahoe-lafs stucks at this file.

[daira]

See also ​https://github.com/LeastAuthority/leastauthority.com/issues/363.

[exarkun]

The established line of development on the "cloud backend" branch has been abandoned. This ticket is being closed as part of a batch-ticket cleanup for "cloud backend"-related tickets.

If this is a bug, it is probably genuinely no longer relevant. The "cloud backend" branch is too large and unwieldy to ever be merged into the main line of development (particularly now that the Python 3 porting effort is significantly underway).

If this is a feature, it may be relevant to some future efforts - if they are sufficiently similar to the "cloud backend" effort - but I am still closing it because there are no immediate plans for a new development effort in such a direction.

Tickets related to the "leasedb" are included in this set because the "leasedb" code is in the "cloud backend" branch and fairly well intertwined with the "cloud backend". If there is interest in lease implementation change at some future time then that effort will essentially have to be restarted as well.