Hi,
The error occurs or is detected by XrdClHttp:
[2021-05-06 08:53:09.092614 +0200][Error ][XrdClHttp ] Could not read URL: http:[log in to unmask]:8000//path/to/file?, error: [ERROR] Internal error: no such device or address: Result Invalid Read in request after 3 attempts
Now we have to figure out why it happens in XrdClHttp for the original source server. I'd guess there is some issue with file size.
What files-size does xrootd report at open / attach time? Is this is the same as file-size on the server?
What version of xrootd is this?
I've never used XrdClHttp so I don;t know how it's packaged / versioned ... does it have a separate version?
Cheers,
Matevz
On 5/10/21 3:07 AM, Bertrand RIGAUD wrote:
> Hello,
>
> well I don't think XcacheH is related to this issue. It's the same behaviour whether or not XcacheH is activated
>
> in xcache data folder, I have the file but the size is just under the entire size (the last chunk is missing)
> it depends on the pfc.blocksize I choose.
>
> let's say I have a file of 10MB and a pfc.blocksize set to 4MB, my downloaded file (in xcache data folder and by extension on the client machine) will be 8MB, and, in the xcache logs, I will have two 4MB chunks OK, and the last chunk will be failed and it will be mentionned that the rest (2MB) can't be downloaded because it cannot be read.
>
> [2021-05-10 10:30:18.127994 +0200][Error ][XrdClHttp ] Could not read URL: http://u23@source_server:8000//path/to/the/file?, error: [ERROR] Internal error: no such device or address: Result Invalid Read in request after 3 attempts
>
>
>
> I performed another test:
>
> I downloaded the file from the source server using curl. I have the fully downloaded file (same amount of bytes that is told by curl "Content-Length" attribute).
> I copied this file on a simple VM at our site and expose it through a basic http server (python -m SimpleHTTPServer 80)
> I downloaded the entire file through xcache! No error message in xcache logs, file is fully downloaded on xcache data folder and on client machine.
>
> So,
>
> there is no problem with the file itself
> there is no problem when downloading from the source server using curl or wget
> there is no problem between xcache and my basic http server
> but there is a problem between xcache and the source server
>
> What in the communication between xcache and the source server can prevents from reading the last chunk of a file?
>
> regards,
>
> Bertrand Rigaud
>
> Centre de Calcul de l'IN2P3 - CNRS
> 21 avenue Pierre de Coubertin
> 69627 Villeurbanne CEDEX
> Tél : 04.78.93.08.80
>
> ----- Mail original -----
> De: "Yang, Wei" <[log in to unmask]>
> À: "Bertrand RIGAUD" <[log in to unmask]>, "xrootd-l" <[log in to unmask]>
> Envoyé: Samedi 8 Mai 2021 00:46:50
> Objet: Re: http ingest using xcache fails
>
> Hmm, I think XcacheH is still more or less experimental. That said, it should still work. Can you go inside the cache directory to find a file name http/path/to/my/file and see if that file is fully cache (size, checksum) ?
>
> regards,
> --
> Wei Yang | [log in to unmask] | 650-926-3338(O)
>
> -----Original Message-----
> From: <[log in to unmask]> on behalf of Bertrand RIGAUD <[log in to unmask]>
> Date: Thursday, May 6, 2021 at 4:47 AM
> To: <[log in to unmask]>
> Subject: http ingest using xcache fails
>
> Hi,
>
> Trying to deploy this architecture (https://cvmfs.readthedocs.io/en/stable/_images/xcache2.svg), I'm facing a problem when downloading a file through http.
>
> Everythting works well till the last chunk is downloaded.
>
> As an example, here is a simple curl performed from the client machine (and this is the same behaviour with cvmfs client) :
>
> ### Through xcache server ###
>
> $ curl -v -o file1 http://my_xcache_server:1094//http://path/to/my/file
> % Total % Received % Xferd Average Speed Time Time Time Current
> Dload Upload Total Spent Left Speed
> 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* About to connect() to my_xcache_server port 1094 (#0)
> * Trying xxx.xxx.xxx.xxx...
> * Connected to my_xcache_server (xxx.xxx.xxx.xxx) port 1094 (#0)
> > GET //http://path/to/my/file HTTP/1.1
> > User-Agent: curl/7.29.0
> > Host: my_xcache_server:1094
> > Accept: */*
> >
> < HTTP/1.1 200 OK
> < Connection: Keep-Alive
> < Content-Length: 506173152
> <
> { [data not shown]
> 99 482M 99 480M 0 0 57.9M 0 0:00:08 0:00:08 --:--:-- 29.9M* transfer closed with 2856672 bytes remaining to read
> 99 482M 99 480M 0 0 57.7M 0 0:00:08 0:00:08 --:--:-- 11.5M
> * Closing connection 0
> curl: (18) transfer closed with 2856672 bytes remaining to read
>
>
> ### Direct download ###
>
> curl -v -o file2 http://path/to/my/file
> % Total % Received % Xferd Average Speed Time Time Time Current
> Dload Upload Total Spent Left Speed
> 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* About to connect() to source_server port 8000 (#0)
> * Trying 145.146.100.30...
> * Connected to source_server (xxx.xxx.xxx.xxx) port 8000 (#0)
> > GET path/to/my/file HTTP/1.1
> > User-Agent: curl/7.29.0
> > Host: source_server:8000
> > Accept: */*
> >
> < HTTP/1.1 200 OK
> < Connection: Keep-Alive
> < Content-Length: 506173152
> <
> { [data not shown]
> 100 482M 100 482M 0 0 101M 0 0:00:04 0:00:04 --:--:-- 101M
> * Connection #0 to host source_server left intact
>
> ### Xcache server logs (last chunk) ###
>
> 210506 08:53:05 155627 sysXrdHttp: XrdHttpReq::Data! final=1
> 210506 08:53:05 155627 unknown.2:23@clientmachine sysXrdHttp: PostProcessHTTPReq req: 2 reqstate: 481
> 210506 08:53:05 155627 unknown.2:23@clientmachine sysXrdHttp: Got data vectors to send:1
> 210506 08:53:05 155627 sysXrdHttp: Sending 1048576 bytes
> 210506 08:53:05 155627 unknown.2:23@clientmachine sysXrdHttp: Process. lp:0 reqstate: 481
> 210506 08:53:05 155627 unknown.2:23@clientmachine sysXrdHttp: Process is exiting rc:0
> 210506 08:53:05 155627 XrdPfc_IO: dump Read() 0x7fc1d00019f0 off: 503316480 size: 1048576 http:[log in to unmask]:8000/http/source.server:8000/path/to/file?
> 210506 08:53:05 155627 XrdPfc_File: dump Read() idx 120 http/source.server:8000/path/to/file
> 210506 08:53:05 155627 XrdPfc_File: dump inc_ref_count 0x7fc1a0403530 refcnt 1 http/source.server:8000/path/to/file
> 210506 08:53:05 155627 XrdPfc_File: dump Read() 0x7fc1f0028000inc_ref_count for existing block 0x7fc1a0403530 idx = 120 http/source.server:8000/path/to/file
> XcacheH: stagein list snapshot: available workers: 10, list length: 0
> [2021-05-06 08:53:09.092614 +0200][Error ][XrdClHttp ] Could not read URL: http:[log in to unmask]:8000//path/to/file?, error: [ERROR] Internal error: no such device or address: Result Invalid Read in request after 3 attempts
> 210506 08:53:09 155645 XrdPfc_File: dump Prefetch enter to check download status http/source.server:8000/path/to/file
> 210506 08:53:09 155645 XrdPfc_File: debug Prefetch file is complete, stopping prefetch. http/source.server:8000/path/to/file
> 210506 08:53:09 155626 XrdPfc_File: dump ProcessBlockResponse block=0x7fc1a0403530, idx=120, off=503316480, res=-6 http/source.server:8000/path/to/file
> 210506 08:53:09 155626 XrdPfc_File: debug ProcessBlockResponse after failed prefetch on io 0x7fc1d00019f0 disabling prefetching on this io. http/source.server:8000/path/to/file
> 210506 08:53:09 155626 XrdPfc_File: error ProcessBlockResponse block 0x7fc1a0403530, idx=120, off=503316480 error=-6 http/source.server:8000/path/to/file
> 210506 08:53:09 155627 XrdPfc_File: dump Read() requested block finished 0x7fc1a0403530, is_failed()=True http/source.server:8000/path/to/file
> 210506 08:53:09 155627 XrdPfc_File: error Read() io 0x7fc1d00019f0, block 120 finished with error 6 no such device or address http/source.server:8000/path/to/file
> 210506 08:53:09 155627 XrdPfc_File: dump Read() dec_ref_count 0x7fc1a0403530 idx = 120 http/source.server:8000/path/to/file
> 210506 08:53:09 155627 XrdPfc_File: dump free_block block 0x7fc1a0403530 idx = 120 http/source.server:8000/path/to/file
> 210506 08:53:09 155627 XrdPfc_IO: warning Read() error in File::Read(), exit status=-6, error=no such device or address http:[log in to unmask]:8000/http/source.server:8000/path/to/file?
> 210506 08:53:09 155627 ofs_read: unknown.2:23@clientmachine Unable to read /http:/source.server:8000/path/to/file; no such device or address
> 210506 08:53:09 155627 sysXrdHttp: XrdHttpReq::Error
> 210506 08:53:09 155627 unknown.2:23@clientmachine sysXrdHttp: PostProcessHTTPReq req: 2 reqstate: 482
> 210506 08:53:09 155627 unknown.2:23@clientmachine sysXrdHttp: PostProcessHTTPReq mapping Xrd error [3005] to status code [500]
> 210506 08:53:09 155627 unknown.2:23@clientmachine sysXrdHttp: Stopping request because more data is expected but no data has been read.
> 210506 08:53:09 155627 sysXrdHttp: XrdHttpReq request ended.
> 210506 08:53:09 155627 sysXrdHttp: Cleanup
> 210506 08:53:09 155627 sysXrdHttp: Reset
> 210506 08:53:09 155627 sysXrdHttp: XrdHttpReq request ended.
> 210506 08:53:09 155627 XrootdXeq: unknown.2:23@clientmachine disc 0:00:09 (send failure)
> 210506 08:53:09 155627 XrdPfc_File: debug ioActive start for io 0x7fc1d00019f0 http/path/to/file
> 210506 08:53:09 155627 XrdPfc_File: info ioActive for io 0x7fc1d00019f0, active_prefetches 0, allow_prefetching False, ioactive_false_reported False, ios_in_detach 0
> 210506 08:53:09 155627 XrdPfc_File: info io_map.size() 1, block_map.size() 0, file http/path/to/file
> 210506 08:53:09 155627 XrdPfc_File: info ioActive for io 0x7fc1d00019f0 returning False, file http/path/to/file
> 210506 08:53:09 155627 XrdPfc_IO: info DetachFinalize() 0x7fc1d00019f0
> 210506 08:53:09 155627 XrdPfc_Cache: debug ReleaseFile http/path/to/file, io 0x7fc1d00019f0
> 210506 08:53:09 155627 XrdPfc_File: debug RemoveIO() io = 0x7fc1d00019f0 http/path/to/file
> 210506 08:53:09 155627 XrdPfc_Cache: debug dec_ref_cnt http/path/to/file, cnt at entry = 1
> 210506 08:53:09 155627 XrdPfc_File: debug FinalizeSyncBeforeExit requesting sync to write detach stats http/path/to/file
> 210506 08:53:09 155627 XrdPfc_Cache: debug dec_ref_cnt http/path/to/file, scheduling final sync
> 210506 08:53:09 155627 XrdPfc_IO: debug ~IOEntireFile() 0x7fc1d00019f0 http:[log in to unmask]:8000/http/path/to/file?
> 210506 08:53:09 155627 Posix_PrepIODisable: Disabling defered open http:[log in to unmask]:8000//path/to/file?
> 210506 08:53:09 160872 XrdPfc_File: dump Sync() http/path/to/file
> 210506 08:53:09 160872 XrdPfc_File: dump Sync 0 blocks written during sync http/path/to/file
> 210506 08:53:09 160872 XrdPfc_Cache: debug dec_ref_cnt http/path/to/file, cnt at entry = 1
> 210506 08:53:09 160872 XrdPfc_File: debug FinalizeSyncBeforeExit sync not required http/path/to/file
> 210506 08:53:09 160872 XrdPfc_Cache: debug dec_ref_cnt http/path/to/file, cnt after sync_check and dec_ref_cnt = 0
> 210506 08:53:09 160872 XrdPfc_File: debug ~File() close info http/path/to/file
> 210506 08:53:09 160872 XrdPfc_File: debug ~File() close output http/path/to/file
> 210506 08:53:09 160872 XrdPfc_File: debug ~File() ended, prefetch score = 3.95238 http/path/to/file
> 210506 08:53:11 155631 Posix_DDestroy: DLY destory of 1 objects; 0 already lost.
> 210506 08:53:11 155631 Posix_DDestroy: DLY destory end; 0 objects deferred and 0 lost.
>
> ### Xcache config ###
>
> all.role proxy server
>
> all.export /http:/
> all.export /https:/
>
> ofs.osslib libXrdPss.so
>
> xrootd.seclib /usr/lib64/libXrdSec.so
>
> pss.origin =http,https
>
> # US data servers
> pss.permit source.server
> pss.permit source.server
> pss.permit source.server
> pss.permit source.server
> pss.permit source.server
> pss.permit source.server
> pss.permit source.server
> # EU data servers
> pss.permit source.server
> pss.permit source.server
> pss.permit source.server
>
> pss.cachelib libXrdPfc.so
> pss.config streams 8
>
> # XcacheH
> pss.namelib -lfncachesrc+ /usr/lib64/XrdName2NameXcacheH.so cacheLife=1d cacheBlockSize=4m
> pss.ccmlib /usr/lib64/XrdName2NameXcacheH.so
>
> oss.localroot /xcache/ns
>
> # Metadata directories (cinfo files)
> oss.space meta /xcache/meta
>
> # Data directories
> oss.space data /xcache/data
>
> # Xcache spaces assignement
> pfc.spaces data meta
>
> if exec xrootd
> xrd.protocol http:1094 libXrdHttp.so
> fi
>
> pfc.diskusage 0.90 0.95
>
> pfc.ram 6g
> pfc.blocksize 4M
> pfc.prefetch 32
>
> pfc.trace dump
> http.trace all
> pss.trace all
> pss.debug
>
> ### xrootd version: 5.1.1 ###
>
> As a result, I got an almost file downloaded on client side, and also in xcache server, cached data is an almost file. Just this last chunk missing.
>
> Are there directives missing in congig file?
>
> Thank you,
>
> Bertrand Rigaud
>
> Centre de Calcul de l'IN2P3 - CNRS
> 21 avenue Pierre de Coubertin
> 69627 Villeurbanne CEDEX
> Tél : 04.78.93.08.80
>
> ########################################################################
> Use REPLY-ALL to reply to list
>
> To unsubscribe from the XROOTD-L list, click the following link:
> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-L&A=1
>
> ########################################################################
> Use REPLY-ALL to reply to list
>
> To unsubscribe from the XROOTD-L list, click the following link:
> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-L&A=1
>
########################################################################
Use REPLY-ALL to reply to list
To unsubscribe from the XROOTD-L list, click the following link:
https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-L&A=1
