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.