Errors while uploading - Githubissues

gmazzamuto commented 1 year ago

Dear all,

I am seeing errors while uploading some Zarr files:

PATH                                                                                        SIZE     ERRORS    UPLOAD STATUS      MESSAGE                                                                                                    
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS03_stain-NeuN_SPIM.ome.zarr         28.2 GB    0         100% done                                                                                                                   
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS03_stain-Somatostatin_SPIM.ome.zarr 27.0 GB    0         100% done                                                                                                                   
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS04_stain-Calretinin_SPIM.ome.zarr   29.8 GB    0         100% done                                                                                                                   
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS04_stain-NeuN_SPIM.ome.zarr         30.0 GB    0         100% done                                                                                                                   
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS04_stain-Somatostatin_SPIM.ome.zarr 28.3 GB    0         100% done                                                                                                                   
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS05_stain-Calretinin_SPIM.ome.zarr   26.8 GB    0          49% ERROR       Error 400 while sending PUT request to https://dandiarchive.s3.amazonaws.com/zarr/40e22a9d-3cf4-4245-aa...
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS05_stain-NeuN_SPIM.ome.zarr         28.1 GB    0           6% ERROR       501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba...
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS05_stain-Somatostatin_SPIM.ome.zarr 26.7 GB    0          56% ERROR       501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/fde6ba34-0c45-49b...
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS06_stain-Calretinin_SPIM.ome.zarr   28.0 GB    0         100% done                                                                                                                   
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS06_stain-NeuN_SPIM.ome.zarr         29.0 GB    0          53% ERROR       501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/e001a5a3-3949-43b...
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS06_stain-Somatostatin_SPIM.ome.zarr 27.7 GB    0         100% done                                                                                                                   
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS07_stain-Calretinin_SPIM.ome.zarr   30.3 GB    0          26% ERROR       Error 400 while sending PUT request to https://dandiarchive.s3.amazonaws.com/zarr/4a299473-0876-4f96-b8...
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS07_stain-NeuN_SPIM.ome.zarr         32.0 GB    0          39% ERROR       501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/be69829d-16dd-48c...
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS07_stain-Somatostatin_SPIM.ome.zarr 30.3 GB    0          53% ERROR       501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/ee44994f-7e2c-45a...
sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS08_stain-Calretinin_SPIM.ome.zarr   29.2 GB    0           2% ERROR       501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/2e5005d7-efd2-493...

Here are some (slightly redacted) excerpts from the log:

2023-03-27T15:49:37+0200 [INFO    ] dandi 3822266:140510692464448 dandi v0.51.0, hdmf v3.5.2, pynwb v2.3.1, h5py v3.8.0
2023-03-27T15:49:37+0200 [INFO    ] dandi 3822266:140510692464448 sys.argv = ['/opt/bin/dandi', 'upload', '--allow-any-path', '--validation', 'ignore', 'sub-I45/ses-SPIM']

2023-03-27T17:01:11+0200 [ERROR   ] dandi 3822266:140508050728704 HTTP connection failed
Traceback (most recent call last):
  File "/opt/lib/python3.8/site-packages/dandi/dandiapi.py", line 210, in request
    for i, attempt in enumerate(
  File "/opt/lib/python3.8/site-packages/tenacity/__init__.py", line 347, in __iter__
    do = self.iter(retry_state=retry_state)
  File "/opt/lib/python3.8/site-packages/tenacity/__init__.py", line 325, in iter
    raise retry_exc.reraise()
  File "/opt/lib/python3.8/site-packages/tenacity/__init__.py", line 158, in reraise
    raise self.last_attempt.result()
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 437, in result
    return self.__get_result()
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result
    raise self._exception
  File "/opt/lib/python3.8/site-packages/dandi/dandiapi.py", line 240, in request
    result.raise_for_status()
  File "/opt/lib/python3.8/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42...

2023-03-27T17:01:23+0200 [ERROR   ] dandi 3822266:140509742302976 Error uploading /NIH/DANDI/000026/sub-I45/ses-SPIM/micr/sub-I45_ses-SPIM_sample-BrocaAreaS05_stain-NeuN_SPIM.ome.zarr:
Traceback (most recent call last):
  File "/opt/lib/python3.8/site-packages/dandi/upload.py", line 240, in process_path
    for r in dfile.iter_upload(
  File "/opt/lib/python3.8/site-packages/dandi/files/zarr.py", line 470, in iter_upload
    size = fut.result()
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 437, in result
    return self.__get_result()
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result
    raise self._exception
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/opt/lib/python3.8/site-packages/dandi/files/zarr.py", line 544, in _upload_zarr_file
    storage_session.put(
  File "/opt/lib/python3.8/site-packages/dandi/dandiapi.py", line 311, in put
    return self.request("PUT", path, **kwargs)
  File "/opt/lib/python3.8/site-packages/dandi/dandiapi.py", line 210, in request
    for i, attempt in enumerate(
  File "/opt/lib/python3.8/site-packages/tenacity/__init__.py", line 347, in __iter__
    do = self.iter(retry_state=retry_state)
  File "/opt/lib/python3.8/site-packages/tenacity/__init__.py", line 325, in iter
    raise retry_exc.reraise()
  File "/opt/lib/python3.8/site-packages/tenacity/__init__.py", line 158, in reraise
    raise self.last_attempt.result()
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 437, in result
    return self.__get_result()
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result
    raise self._exception
  File "/opt/lib/python3.8/site-packages/dandi/dandiapi.py", line 240, in request
    result.raise_for_status()
  File "/opt/lib/python3.8/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42...

2023-03-27T17:36:08+0200 [DEBUG   ] dandi 3822266:140509784250112 Error uploading zarr: HTTPError: Error 400 while sending PUT request to https://dandiarchive.s3.amazonaws.com/zarr/40e22a9d-3cf4-4245-aa7e-400b65381cd4/0/1/6/86....: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>BadDigest</Code><Message>The Content-MD5 you specified did not match what we received.</Message><ExpectedDigest>4f0daa8170fae2bd0b05e09f61b10d66</ExpectedDigest><CalculatedDigest>Zvtu9pNAoZlNjjFTrpMhKQ==</CalculatedDigest><RequestId>1EEDC8B4XNEJNSJ9</RequestId><HostId>AOiMy3L2IOtiyfrA6I+sFe6Nxb0WzDGVoVYyQaTsWWzsSoV9aSl+Y8vGz0oaU8b3u62p9ccCsK4=</HostId></Error>
2023-03-27T17:36:08+0200 [DEBUG   ] dandi 3822266:140509784250112 Cancelling upload

Hope this helps! Giacomo

satra commented 1 year ago

also pinging @AlmightyYakob as there may be both server and cli interactions at play.

yarikoptic commented 1 year ago

could you please share the log file which should have been mentioned at the end of the process? May be would help to see what is not implemented and thus causing 501.

gmazzamuto commented 1 year ago

I can't see any meaningful information in the log file besides the snippets I have pasted above, I'm attaching it here anyways! 20230327134937Z-3822266.log.gz

jwodder commented 1 year ago

I see two types of errors in the log file:

501 errors of the kind seen previously in #1033. As before, I maintain that this can only be caused by a faulty filesystem.
400 errors caused by a digest mismatch when uploading. Unless something was modifying the local files during the upload process, I also blame this on the file system.

@gmazzamuto What type of filesystem are you uploading from? Do the errors happen again if you upload again?

gmazzamuto commented 1 year ago

The files are not modified during the upload. I am uploading from an NFS share. When I reuploaded, there were no errors. The upload I am doing right now is showing two 400 errors and one 501 error.

yarikoptic commented 1 year ago

NFS can be fun, depending on the enthusiasm (or lack of such) of admins ;) At some point even, to reduce "fun", I just made it all plain sync (read -- slow) to avoid any kind of surprises which I had of various kinds. How "recent" the data files you are uploading were created/modified in respect to their time point of upload? may be we should start recording mtime of files we upload so if smth goes wrong we could check if mtime did not change but I am neither sure it is the whole situation here.

gmazzamuto commented 1 year ago

Hi Yarik, the files where created several hours before the upload. They are stored on a NAS server with RAID and accessed through an NFS share. Do you think the problems I am seeing are due to the network share? I've never noticed data corruption before.

During the last upload I got several errors, including a 501 but with a slightly different stack trace:

Traceback (most recent call last):                                                                                                                                                                                                           
  File "/opt/bin/dandi", line 8, in <module>                                                                                                                                                                           
    sys.exit(main())                                                                                                                                                                                                                         
  File "/opt/lib/python3.8/site-packages/click/core.py", line 1130, in __call__                                                                                                                                        
    return self.main(*args, **kwargs)                                                                                                                                                                                                        
  File "/opt/lib/python3.8/site-packages/click/core.py", line 1055, in main                                                                                                                                            
    rv = self.invoke(ctx)                                                                                                                                                                                                                    
  File "/opt/lib/python3.8/site-packages/click/core.py", line 1657, in invoke                                                                                                                                          
    return _process_result(sub_ctx.command.invoke(sub_ctx))                                                                                                                                                                                  
  File "/opt/lib/python3.8/site-packages/click/core.py", line 1404, in invoke                                                                                                                                          
    return ctx.invoke(self.callback, **ctx.params)                                                                                                                                                                                           
  File "/opt/lib/python3.8/site-packages/click/core.py", line 760, in invoke                                                                                                                                           
    return __callback(*args, **kwargs)                                                                                                                                                                                                       
  File "/opt/lib/python3.8/site-packages/click/decorators.py", line 38, in new_func                                                                                                                                    
    return f(get_current_context().obj, *args, **kwargs)                                                                                                                                                                                     
  File "/opt/lib/python3.8/site-packages/dandi/cli/base.py", line 102, in wrapper                                                                                                                                      
    return f(*args, **kwargs)                                                                                                                                                                                                                
  File "/opt/lib/python3.8/site-packages/dandi/cli/cmd_upload.py", line 98, in upload                                                                                                                                  
    upload(                                                                                                                                                                                                                                  
  File "/opt/lib/python3.8/site-packages/dandi/upload.py", line 343, in upload                                                                                                                                         
    raise upload_err                                                                                                                                                                                                                         
  File "/opt/lib/python3.8/site-packages/dandi/upload.py", line 240, in process_path
    for r in dfile.iter_upload(                            
  File "/opt/lib/python3.8/site-packages/dandi/files/zarr.py", line 470, in iter_upload
    size = fut.result()                                    
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 437, in result                                          
    return self.__get_result()                             
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result                                    
    raise self._exception                                  
  File "/usr/lib/python3.8/concurrent/futures/thread.py", line 57, in run                                             
    result = self.fn(*self.args, **self.kwargs)            
  File "/opt/lib/python3.8/site-packages/dandi/files/zarr.py", line 544, in _upload_zarr_file
    storage_session.put(                                   
  File "/opt/lib/python3.8/site-packages/dandi/dandiapi.py", line 311, in put
    return self.request("PUT", path, **kwargs)             
  File "/opt/lib/python3.8/site-packages/dandi/dandiapi.py", line 210, in request
    for i, attempt in enumerate(                           
  File "/opt/lib/python3.8/site-packages/tenacity/__init__.py", line 347, in __iter__
    do = self.iter(retry_state=retry_state)                
  File "/opt/lib/python3.8/site-packages/tenacity/__init__.py", line 325, in iter
    raise retry_exc.reraise()                              
  File "/opt/lib/python3.8/site-packages/tenacity/__init__.py", line 158, in reraise
    raise self.last_attempt.result()                       
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 437, in result                                          
    return self.__get_result()                             
  File "/usr/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result                                    
    raise self._exception                                  
  File "/opt/lib/python3.8/site-packages/dandi/dandiapi.py", line 240, in request
    result.raise_for_status()                              
  File "/opt/lib/python3.8/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)                                                                    
requests.exceptions.HTTPError: 501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/d5f67f3d-144c-447e-aae0-ca5b979c648d/0/1/22/58?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F
20230330%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230330T134214Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=e65355bb3725ca73f8d313d9e907ddbbeb00c3e7868d392b233b8eaf2eb7b1b5

yarikoptic commented 1 year ago

@jwodder what about those "not implemented" 501s coming from AWS -- what are those exactly about and isn't it us who submit those requests?

jwodder commented 1 year ago

@yarikoptic As before, it's the same problem as #1033.

yarikoptic commented 1 year ago

Hi Yarik, the files where created several hours before the upload. They are stored on a NAS server with RAID and accessed through an NFS share. Do you think the problems I am seeing are due to the network share?

In that #1033 it also was NFS over beegfs, so so far it is some common aspect here. Do you know your underlying NAS server filesystem?

I've never noticed data corruption before.

it might be not necessarily "corruption" but some other odd behavior/delayed metadata propagation. E.g. in https://github.com/dandi/dandi-cli/issues/1033#issuecomment-1176447518 @jwodder hypothesizes that may be some inability to get file size reported forces requests to

sends a "Transfer-Encoding" (with value "chunked") when it's unable to determine the size of the request payload .. The only reason I can think of as to why getting the file size should fail would be due to some sort of filesystem hiccup.

During the last upload I got several errors, including a 501 but with a slightly different stack trace: ... requests.exceptions.HTTPError: 501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/d5f67f3d-144c-447e-aae0-ca5b979c648d/0/1/22/58?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F 20230330%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230330T134214Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=e65355bb3725ca73f8d313d9e907ddbbeb00c3e7868d392b233b8eaf2eb7b1b5

@jwodder believes (and I trust him on that) that it is likely that issue of chunked encoding described in https://github.com/dandi/dandi-cli/issues/1033#issuecomment-1176447518 and cited above.

@jwodder - do you mean this https://github.com/psf/requests/blob/HEAD/requests/models.py#L549 or some other location? how could we instrument in our code to discover more about the situation better?

jwodder commented 1 year ago

@yarikoptic That's one of the location involved, yes. What exactly do you want to discover?

yarikoptic commented 1 year ago

@yarikoptic That's one of the location involved, yes. What exactly do you want to discover?

ultimately -- resolution to this issue so that there is no error during uploading. For that IMHO we need to troubleshoot further and instrument to gather

some evidence that your idea on the underlying issue is right on. If it is (refusal to stat a size) it sounds really odd that size would not be reported, and IMHO then should be reported to the admins of those systems
workaround: presumably (double check for this particular case in the logs, report back) we are retrying. It sounds really unlikely that the same filesystem fluke happens reproducibly for an extended period of time. If it happens at requests level reproducibly -- we should be able to detect it at dandi-cli level when catching that exception -- instrument there to confirm that it is indeed about inability to request the size

yarikoptic commented 1 year ago

Found another old NFS related issue: https://github.com/dandi/dandi-cli/issues/764

jwodder commented 1 year ago

@yarikoptic Could you be more precise about exactly what sort of instrumentation you want? Your first bullet point sounds like you want to detect & report when requests fails to get a file's size, and your second bullet point also sounds like you want to detect & report when requests fails to get a file's size (except that the second bullet says to do this by inspecting some exception, but the only exception dandi-cli sees is raised in response to S3 returning a 501 error). Am I misinterpreting what you're saying, or are you asking for the exact same thing twice with completely different words?

yarikoptic commented 1 year ago

Your first bullet point sounds like you want to detect & report when requests fails to get a file's size

correct

and your second bullet point also ... Am I misinterpreting what you're saying, or are you asking for the exact same thing twice with completely different words?

in the 2nd point I

asked to double check if we are retrying to send a file on that particular 501 error from AWS
continued arguing that if we get to that 501 exception handling after initial error we must fail to get the size the way requests fails to get the size if on retry requests also fails to get the size. If we do not fail to get the size, but requests again leads us to 501 then it is either
- it is not the "size getting" which flips it and we better provision more,
- we do get size somehow differently
- some other factors within requests code which cause it to fail there.

jwodder commented 1 year ago

@yarikoptic Yes, we are retrying on the 501 errors. For example, grepping for one of the failed upload URLs from the logs in this comment gives:

2023-03-27T17:00:04+0200 [DEBUG   ] dandi 3822266:140508050728704 PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:11+0200 [DEBUG   ] urllib3.connectionpool 3822266:140508050728704 https://dandiarchive.s3.amazonaws.com:443 "PUT /zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228 HTTP/1.1" 500 None
2023-03-27T17:00:13+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:15+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:18+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:21+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:24+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:29+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:34+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:41+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:49+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:00:59+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:01:11+0200 [WARNING ] dandi 3822266:140508050728704 Retrying PUT https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
requests.exceptions.HTTPError: 501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
2023-03-27T17:01:12+0200 [DEBUG   ] dandi 3822266:140509742302976 Error uploading zarr: HTTPError: 501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228
requests.exceptions.HTTPError: 501 Server Error: Not Implemented for url: https://dandiarchive.s3.amazonaws.com/zarr/0205ef2e-71ba-4ba1-a4b3-489ee5efe02b/0/0/8/42?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAUBRWC5GAEKH3223E%2F20230327%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Date=20230327T145955Z&X-Amz-Expires=600&X-Amz-SignedHeaders=content-md5%3Bhost%3Bx-amz-acl&X-Amz-Signature=70c3f2c08fc29ea209c8a60fb366fa4619cb2d7190b9b5030c82552cad51a228

continued arguing that if we get to that 501 exception handling after initial error we must fail to get the size the way requests fails to get the size if on retry requests also fails to get the size.

So, if & when the 501 error occurs (only for the first time for a given uploaded file?), you want dandi-cli to try to get the filesize the same way requests does it, and then what?

yarikoptic commented 1 year ago

NB I had a question are we "retrying at a proper level" or just sending the "bad" `Content-Length` over and over again? Seems to be yes:

here is the stack for the point where `Content-Length` is assigned: ``` (Pdb) /usr/lib/python3.11/threading.py(995)_bootstrap() -> self._bootstrap_inner() /usr/lib/python3.11/threading.py(1038)_bootstrap_inner() -> self.run() /usr/lib/python3.11/threading.py(975)run() -> self._target(*self._args, **self._kwargs) /usr/lib/python3.11/concurrent/futures/thread.py(83)_worker() -> work_item.run() /usr/lib/python3.11/concurrent/futures/thread.py(58)run() -> result = self.fn(*self.args, **self.kwargs) /home/yoh/proj/dandi/dandi-cli-master/dandi/files/zarr.py(544)_upload_zarr_file() -> storage_session.put( /home/yoh/proj/dandi/dandi-cli-master/dandi/dandiapi.py(311)put() -> return self.request("PUT", path, **kwargs) /home/yoh/proj/dandi/dandi-cli-master/dandi/dandiapi.py(227)request() -> result = self.session.request( /home/yoh/proj/misc/requests/requests/sessions.py(573)request() -> prep = self.prepare_request(req) /home/yoh/proj/misc/requests/requests/sessions.py(484)prepare_request() -> p.prepare( /home/yoh/proj/misc/requests/requests/models.py(371)prepare() -> self.prepare_body(data, files, json) > /home/yoh/proj/misc/requests/requests/models.py(550)prepare_body() -> if length: ``` so the `sessions.py(573)request()` is the request we are retrying with tenacity (in the original traceback) so I guess should be all good,.

So, if & when the 501 error occurs (only for the first time for a given uploaded file?), you want dandi-cli to try to get the filesize the same way requests does it, and then what?

if we can get the file size there then it is one of those 3 cases I listed which could be at play here. Most likely imho is that it is some other cause than size getting. But to entirely rule it out -- we would need to overload

❯ grep 'def super' requests/utils.py
def super_len(o):

which is what is used by requests, and instrument to log the "body" (what file it is) and returned size. This way we would discover for sure if that is somehow size to blame. What if we start from there and add instrumentation of that function to be triggered by e.g. DANDI_DEVEL_INSTRUMENT_REQUESTS_SUPERLEN env var?

yarikoptic commented 1 year ago

@gmazzamuto would you be so kind to try with fresh 0.52.0 release which would log more information about failing requests -- may be it would give us more clue on what is going on.

yarikoptic commented 1 year ago

@gmazzamuto , if you could install from GitHub master branch, and run with DANDI_DEVEL_INSTRUMENT_REQUESTS_SUPERLEN=1 environment variable set, would be even better and logs could help us to figure out more

gmazzamuto commented 1 year ago

Sure, I can give it a try. But I have completed my uploads for now, there are only some small files left (photos and json sidecar files). I guess it's more likely to happen with larger files, but I can try anyways

yarikoptic commented 1 year ago

any odd behaviors you were (un)lucky to run into @gmazzamuto ?

gmazzamuto commented 1 year ago

Hi Yarik, I haven't had the chance to upload new data yet, I will try in the coming days then I'll let you know how it goes!

yarikoptic commented 1 year ago

@gmazzamuto we are holding our breath! ;-)

gmazzamuto commented 1 year ago

Hi Yarik, I haven't forgotten about this, but I am just waiting for a bunch of new data to upload to see if the error can be triggered again. It should be ready soon

gmazzamuto commented 1 year ago

Hi Yarik, I am getting ready for new uploads next week. Are the instructions still valid? Install from GitHub master branch and run with DANDI_DEVEL_INSTRUMENT_REQUESTS_SUPERLEN=1

yarikoptic commented 1 year ago

yes, besides that pypi release (since 0.53.0) would be as good too now.

yarikoptic commented 11 months ago

@gmazzamuto did you get a chance to gather more debugging information on this issue?

gmazzamuto commented 11 months ago

Yes I have tried recently and I still got the same errors. I had to restart the upload a couple of times. I have the log file but it's really huge, so I haven't uploaded it. I will soon try again, maybe with a smaller payload

gmazzamuto commented 10 months ago

Hi folks,

I am still getting those errors. Here attached is a heavily redacted log file with many lines deleted, I've left the lines around where the error happened.

I've deleted all the lines of this kind:

The `/NIH/DANDI/000026/rawdata_biolab/I60/20220829_I60_49_LeftDet_638_RightDet_488/tiff_right/x_132.00000_y_099.60000_z_000.00000__cam_r.ome.tif` file was not matched by any regex schema entry.

Estimating digests for /NIH/DANDI/000026/sub-I59/ses-SPIM/micr/sub-I59_ses-SPIM_sample-BrocaAreaS27_stain-Calretinin_SPIM.ome.zarr/0/0/84/55

and the successful transfers.

20231122142221Z-639852.log.gz

jwodder commented 10 months ago

I found the problem:

2023-11-22T17:44:16+0100 [DEBUG ] dandi 639852:140007712995072 requests.utils.super_len() reported 0 for <_io.BufferedReader name='/NIH/DANDI/000026/sub-I59/ses-SPIM/micr/sub-I59_ses-SPIM_sample-BrocaAreaS28_stain-Somatostatin_SPIM.ome.zarr/0/1/6/12'>

If super_len() returns 0, requests will use "chunked" encoding, which AWS apparently doesn't support. It's my understanding that uploading an empty file to AWS (and thus to Dandi Archive) isn't something that can be done in the first place, so (aside from the UX around the error message) the upload is correct to error.

yarikoptic commented 10 months ago

@gmazzamuto can you confirm that /NIH/DANDI/000026/sub-I59/ses-SPIM/micr/sub-I59_ses-SPIM_sample-BrocaAreaS28_stain-Somatostatin_SPIM.ome.zarr/0/1/6/12 is an empty (0 length) file?

It's my understanding that uploading an empty file to AWS (and thus to Dandi Archive) isn't something that can be done in the first place

What do you mean exactly? For DANDI we indeed disallow empty blobs, but S3 does support empty files [*] so if zarr needs (yet to be checked) an empty file we should be able to do it on S3.

Since I am not an expert in zarr -- does having an empty file within zarr makes sense. @satra do you know? so far chatgpt says "No" to me, but there could be empty folders! (for empty datasets, not sure if they could safely be omitted but we can't have empty folder on S3)

if it does -- I guess we would need to make sure we could "upload" 0-length file to S3 (might be some custom/touch call without actual content transfer since none to be done). If it doesn't -- we should add to zarr validation and fail informatively if such file is found within a zarr.

[*] https://aws.amazon.com/s3/faqs/ says "Individual Amazon S3 objects can range in size from a minimum of 0 bytes to a maximum of 5 TB. "

jwodder commented 10 months ago

Previous issue on uploading empty files to the Archive: https://github.com/dandi/dandi-archive/issues/168

gmazzamuto commented 10 months ago

@yarikoptic No, it's not an empty file. It's 965KiB. Indeed, I reuploaded the whole .ome.zarr that errored and now it worked.

yarikoptic commented 10 months ago

Previous issue on uploading empty files to the Archive: dandi/dandi-archive#168

yeap, no blobs of size 0 are still allowed although indeed it is somewhat of a superficial restriction. And apparently the case here is also that we do not have a 0-length file, but rather that requests.utils.super_len() managed to report 0 on the file which is not empty. From looking at the function and https://github.com/psf/requests/blob/main/src/requests/utils.py#L143

        try:
            fileno = o.fileno()
        except (io.UnsupportedOperation, AttributeError):
            # AttributeError is a surprising exception, seeing as how we've just checked
            # that `hasattr(o, 'fileno')`.  It happens for objects obtained via
            # `Tarfile.extractfile()`, per issue 5229.
            pass
        else:
            total_length = os.fstat(fileno).st_size

it is not 100% clear on either it was some io.UnsupportedOperation for some reason or indeed os.fstat(fileno).st_size returned 0.

I found nothing in requests to mention NFS, but I do know that "NFS is special" and all kinds of oddities could happen there.

@gmazzamuto -- would you mind sharing output of

stat /NIH/DANDI/000026/sub-I59/ses-SPIM/micr/sub-I59_ses-SPIM_sample-BrocaAreaS28_stain-Somatostatin_SPIM.ome.zarr/0/1/6/12

?

@jwodder -- any ideas? if not -- we should instrument your instrumentation further to clarify where the gotcha and either there is some sensible workaround (e.g. sleep). e.g. instead of just printing when super_len returns 0 - do os.fstat on that .fileno and then possibly even smth as calling stat on the .name from outside the python and checking that information -- if both are 0s, then "all cool", must be empty on that round. But if not -- we caught NFS/Python interplay and might be worth reporting to requests depending on what we find. Also do loop few times with a sleep to ensure that value doesn't change within e.g. 5 seconds, if changes -- just NFS to blame, and for us to workaround unless we could unveil some indicator -- please log full output of fstat in such cases, may be mtime/ctime or some other attribute would also be degenerate.

gmazzamuto commented 10 months ago

Here is the output of stat:

File: /NIH/DANDI/000026/sub-I59/ses-SPIM/micr/sub-I59_ses-SPIM_sample-BrocaAreaS28_stain-Somatostatin_SPIM.ome.zarr/0/1/6/12
  Size: 987680          Blocks: 1936       IO Block: 1048576 regular file
Device: 3dh/61d Inode: 244535389962  Links: 1
Access: (0644/-rw-r--r--)  Uid: ( 1000/user)   Gid: ( 1000/group)
Access: 2023-11-22 17:01:35.752336409 +0100
Modify: 2023-11-22 10:14:49.966501429 +0100
Change: 2023-11-22 10:14:49.966501429 +0100
 Birth: -

jwodder commented 10 months ago

@yarikoptic

possibly even smth as calling stat on the .name from outside the python and checking that information

Do you mean invoking an external program that does stat? I don't believe there's a portable way to do that, and I'd rather not blindly try to figure out how to do such a thing in Windows.

But if not -- we caught NFS/Python interplay and might be worth reporting to requests depending on what we find.

I doubt the requests maintainers are going to be willing or able to do anything about NFS being a liar.

yarikoptic commented 10 months ago

@yarikoptic

possibly even smth as calling stat on the .name from outside the python and checking that information

Do you mean invoking an external program that does stat? I don't believe there's a portable way to do that, and I'd rather not blindly try to figure out how to do such a thing in Windows.

AFAIK there no NFS on windows we need to troubleshoot here, so we should be fine. Sure thing if you see a better, non-stat way, ok with me too. The idea was to get "third-party non Python assessment" since after all Python is also not god's given and I personally do not know if it would lead to the same syscall as of stat and no other conditioning.

I doubt the requests maintainers are going to be willing or able to do anything about NFS being a liar.

well, it might at least be worth raising their awareness that NFS is a liar and workarounds might be needed. But first we really need to catch it "red handed".

jwodder commented 10 months ago

@yarikoptic Problem: I don't believe there's a portable way to call stat via an external program on Unix either (unless you want to invoke another programming language like Perl). The best candidate — the stat(1) command — isn't part of POSIX, so the GNU version (used on Linux) and the BSD version (used on macOS) emit different formats and take different options. Also, I strongly suspect that stat(1), Perl, and Python all call stat(2).

jwodder commented 10 months ago

@yarikoptic Setting aside the external program issue for now, what exactly is the flow you want to be added around super_len()? Your comment implies the following:

If super_len() returns 0 on a file-like object:
- Call os.stat() on the file path
- Call os.fstat() on the file object's fileno
- If at least one stat was successful and all successful stats reported a size of zero, then assume the file is genuinely empty and return
- Otherwise, sleep for five(?) seconds and then try again
  - How many tries should there be in total?
  - Should we ever sleep & retry when the stats agree the file is empty?
  - What size value should be returned to requests?
Should these checks also be run if super_len() raises an exception?

Is this the sort of thing you want?

yarikoptic commented 10 months ago

Since we do not expect 0 length files at all:

If super_len() returns 0 on a file-like object:
- for 10 trials:
  - Call super_len() on the file path
  - Call os.stat() on the file path
  - Call os.fstat() on the file object's fileno
  - If any of them fails -- log that ERROR, might be the culprit
  - If any of them non-0 value -- raise Exception with detail (original super_len was 0 but now stat X is not after Y seconds)
  - sleep for 1 second
- DEBUG log that we are returning 0 for the file path after 10 rounds of stats which all were 0s
- return 0
Should these checks also be run if super_len() raises an exception?
- so far we didn't get any error from super_len, right? so let's just keep it as is since then we would not get just 0 returned , right?

yarikoptic commented 10 months ago

@gmazzamuto when will you be uploading again? we now have merged #1370 so if you would use master version of dandi-cli with DANDI_DEVEL_INSTRUMENT_REQUESTS_SUPERLEN=1 we should do even more checks/logging at debug level to hopefully pin down erroneous behavior of NFS here.

gmazzamuto commented 10 months ago

Here is the latest log (again, where I've deleted many lines) with several exceptions of different kinds.

log.txt

jwodder commented 10 months ago

@gmazzamuto Are you sure you were using commit b9a1099 of dandi-cli? I see a log message about a zero-length Zarr file but none of the messages added in #1370.

gmazzamuto commented 10 months ago

no sorry, my fault: I saw a new available version of dandi-cli and installed that without checking if it contained the relevant commit. I'll send the log using the correct version of the client

gmazzamuto commented 10 months ago

Hi all, here is the latest log:

log.txt

jwodder commented 10 months ago

I see the following problems in the log:

2023-12-02T02:15:59+0100 [DEBUG   ] dandi 3030432:140064092833536 requests.utils.super_len() reported 0 for <_io.BufferedReader name='/NIH/DANDI/000026/sub-I62/ses-SPIM/micr/sub-I62_ses-SPIM_sample-BrocaAreaS13_stain-Calretinin_SPIM.ome.zarr/0/1/82/89'>
2023-12-02T02:15:59+0100 [DEBUG   ] dandi 3030432:140064092833536 - Size of 0 is suspicious; double-checking that NFS isn't lying
2023-12-02T02:15:59+0100 [DEBUG   ] dandi 3030432:140064092833536 - stat('/NIH/DANDI/000026/sub-I62/ses-SPIM/micr/sub-I62_ses-SPIM_sample-BrocaAreaS13_stain-Calretinin_SPIM.ome.zarr/0/1/82/89') = os.stat_result(st_mode=33188, st_ino=248398250076, st_dev=61, st_nlink=1, st_uid=5000, st_gid=7000, st_size=312461, st_atime=1701477007, st_mtime=1700979160, st_ctime=1700979160)
2023-12-02T02:15:59+0100 [DEBUG   ] dandi 3030432:140064092833536 - fstat('/NIH/DANDI/000026/sub-I62/ses-SPIM/micr/sub-I62_ses-SPIM_sample-BrocaAreaS13_stain-Calretinin_SPIM.ome.zarr/0/1/82/89') = os.stat_result(st_mode=33188, st_ino=248398250076, st_dev=61, st_nlink=1, st_uid=5000, st_gid=7000, st_size=312461, st_atime=1701477007, st_mtime=1700979160, st_ctime=1700979160)
RuntimeError: requests.utils.super_len() reported size of 0 for '/NIH/DANDI/000026/sub-I62/ses-SPIM/micr/sub-I62_ses-SPIM_sample-BrocaAreaS13_stain-Calretinin_SPIM.ome.zarr/0/1/82/89', but os.stat() reported size 312461 bytes 1 tries later

2023-12-02T07:38:21+0100 [DEBUG   ] dandi 3030432:140061148436224 requests.utils.super_len() reported 0 for <_io.BufferedReader name='/NIH/DANDI/000026/sub-I62/ses-SPIM/micr/sub-I62_ses-SPIM_sample-BrocaAreaS17_stain-NeuN_SPIM.ome.zarr/0/1/32/51'>
2023-12-02T07:38:21+0100 [DEBUG   ] dandi 3030432:140061148436224 - Size of 0 is suspicious; double-checking that NFS isn't lying
2023-12-02T07:38:21+0100 [DEBUG   ] dandi 3030432:140061148436224 - stat('/NIH/DANDI/000026/sub-I62/ses-SPIM/micr/sub-I62_ses-SPIM_sample-BrocaAreaS17_stain-NeuN_SPIM.ome.zarr/0/1/32/51') = os.stat_result(st_mode=33188, st_ino=248625074703, st_dev=61, st_nlink=1, st_uid=5000, st_gid=7000, st_size=1355361, st_atime=1701494494, st_mtime=1700989187, st_ctime=1700989187)
2023-12-02T07:38:21+0100 [DEBUG   ] dandi 3030432:140061148436224 - fstat('/NIH/DANDI/000026/sub-I62/ses-SPIM/micr/sub-I62_ses-SPIM_sample-BrocaAreaS17_stain-NeuN_SPIM.ome.zarr/0/1/32/51') = os.stat_result(st_mode=33188, st_ino=248625074703, st_dev=61, st_nlink=1, st_uid=5000, st_gid=7000, st_size=1355361, st_atime=1701494494, st_mtime=1700989187, st_ctime=1700989187)
RuntimeError: requests.utils.super_len() reported size of 0 for '/NIH/DANDI/000026/sub-I62/ses-SPIM/micr/sub-I62_ses-SPIM_sample-BrocaAreaS17_stain-NeuN_SPIM.ome.zarr/0/1/32/51', but os.stat() reported size 1355361 bytes 1 tries later

Conclusion: NFS is a liar.

yarikoptic commented 10 months ago

"coolio!" another question before we proceed: @jwodder do you think it is pertinent to only size 0 or might be for other occasions that NFS reports wrong size first -- would some check/code fail if file size changes during upload there from the moment of initial call to super_len?

jwodder commented 10 months ago

@yarikoptic

would some check/code fail if file size changes during upload there from the moment of initial call to super_len?

That depends on how the S3 server is implemented. The HTTP standard doesn't seem to specify a behavior when a request has an inaccurate Content-Length, so the server could react however it likes, such as by storing a file with a size that matches the Content-Length but not the uploaded data.

yarikoptic commented 10 months ago

@jwodder

most likely it is a NFS behavior oddity specific for size 0, but let's add (at the end of iter_upload?) a check that file size didn't check from the point when it was initially requested to be uploaded. If changed -- raise an informative exception and blame the filesystem and/or user for having file changed under our "feet"
for files of size 0 -- add a loop alike we have but re-checking at smaller intervals and up to e.g. 2 seconds and if changes, log a warning and proceed with that new size. That should mitigate this issue @gmazzamuto is experiencing and allow for uploads to become more robust.

@gmazzamuto could you share details of kernel version (uname -a) and the mount options (output of mount grepped for that location) so we have a record of what scenario could potentially lead to such odd behavior. Ideally someone should report/clear it up with NFS (kernel) developers.

jwodder commented 10 months ago

@yarikoptic

let's add (at the end of iter_upload?) a check that file size didn't [change] from the point when it was initially requested to be uploaded.

S3 already checks that the uploaded files match the MD5 checksums that the client provided before starting the upload. If a Content-Length were to get set to an inaccurate value and S3 honored it, this check would fail, and the upload would fail with an HTTP error.

for files of size 0 -- add a loop alike we have but re-checking at smaller intervals and up to e.g. 2 seconds and if changes, log a warning and proceed with that new size.

Is this a change to the current loop when spying on super_len() or is this a new loop to be added somewhere else (and, if so, where)?

dandi / dandi-cli

Errors while uploading #1257