Bug 2001386

OK but how to reproduce the problem? What steps? What's unique about the configuration? Or also, how to get more information from curl because it's just a generic error message that could related to writes either to local or network storage.

Created attachment 1820771 [details]
Output of `sudo strace dnf install krusader`

Chris, I wrote everything I know.

As to steps to reproduce:
1. Boot Fedora-KDE-Live-x86_64-34-1.2iso in a virtual machine (I'm running under Windows 10 with VirtualBox).
2. In my environment – `sudo sh -c 'echo sslverify=0 >> /etc/dnf/dnf.conf' or installation of corporate CA root certs
3. Run `dnf install krusader`

As to what is unique about my configuration; I can't think of anything special apart of being inside corporate network with https proxy using corporate CA root certificate and acting as MITM.

As to getting more information from curl; that's something I would like to know, too. Curl (or rather libcurl I guess) is being used by dnf/libdnf and one would have to turn any additional debug info in those I guess.

I attached strace output from `sudo dnf install krusader`.
I can provide any information you need as long as you tell me what exactly you need and how to get it.

My guess is that the proxy is causing problems when librepo is downloading the metadata ranges.  Piotr, could you please run `sudo dnf -v install krusader` and see if that produces `/var/log/dnf.librepo.log`?  If so, could you please attach it here?

Created attachment 1821573 [details]
dnf.librepo.log

Created attachment 1821574 [details]
dnf.log

Created attachment 1821575 [details]
dnf.rpm.log

Jonathan,

thank You for joining in.
I attached dnf.librepo.log, dnf.log and dnf.rpm.log from `sudo dnf -v install krusader`.

This looks very likely to be a bug in zchunk, since it has its own curl download handler that's used by librepo.  Piotr, at some point I'll be providing you with some custom builds of zchunk so we can (hopefully) get some more details.  I'll let you know when I'm ready.

Could it be something similar to https://bugzilla.redhat.com/show_bug.cgi?id=1830512 ?
Should I check the behavior with zchunk disabled for comparison?

BTW this might be a similar bug: https://bugzilla.redhat.com/show_bug.cgi?id=1903444

@

Sorry, that previous comment was a typo.  Piotr, could you please install the specially built librepo from https://koji.fedoraproject.org/koji/taskinfo?taskID=75897661 for your architecture.  This will turn on verbose zchunk logging in dnf (which will output to stderr, not a file).  Can you please include the output in an attachment?

Created attachment 1824339 [details]
Output from `sudo dnf install krusader`

I attached the output of the following command:
`sudo rm -rf /var/cache/dnf && sudo dnf install krusader 2>&1 | tee librepo-output.txt`

Before running above command I installed
https://kojipkgs.fedoraproject.org//work/tasks/7692/75897692/librepo-1.14.1-1.fc34.x86_64.rpm
and company's SSL certificates in Fedora 34 booted from live iso.


I'm afraid there are no additional information in the output in regard to the error we are trying to investigate which is seen at the end of the output:

Fedora 34 - x86_64 - Updates                    1.6 MB/s |  24 MB     00:15    
Errors during downloading metadata for repository 'updates':
  - Curl error (23): Failed writing received data to disk/application for http://fedora.ip-connect.info/linux//updates/34/Everything/x86_64/repodata/0fb800256f5c3558a5a6319b3f647d504a5c1042c1ec3197774d8d5f847a1bbf-updateinfo.xml.zck [Failure writing output to destination]
Error: Failed to download metadata for repo 'updates': Yum repo downloading error: Downloading error(s): repodata/0fb800256f5c3558a5a6319b3f647d504a5c1042c1ec3197774d8d5f847a1bbf-updateinfo.xml.zck - Download failed: Curl error (23): Failed writing received data to disk/application for http://fedora.ip-connect.info/linux//updates/34/Everything/x86_64/repodata/0fb800256f5c3558a5a6319b3f647d504a5c1042c1ec3197774d8d5f847a1bbf-updateinfo.xml.zck [Failure writing output to destination]

Yeah, that's not giving us the details we need, unfortunately.  Can you please run `zckdl -vvvv -s /location/to/existing/updateinfo.zck http://fedora.ip-connect.info/linux//updates/34/Everything/x86_64/repodata/0fb800256f5c3558a5a6319b3f647d504a5c1042c1ec3197774d8d5f847a1bbf-updateinfo.xml.zck` (or whatever the updateinfo url is) and attach the output as an attachment?

You might need to run `sudo dnf install zchunk` to get the zckdl utility.

I have a problem with "/location/to/existing/updateinfo.zck" part.
As the error I got is "Errors during downloading metadata for repository 'updates':" then I guess the updateinfo.zck file should be located in /var/cache/dnf/update-<some hash> directory but this directory is empty.

In the previous comment I meant to write "/var/cache/dnf/updates-<some hash>" instead of "/var/cache/dnf/update-<some hash>" – "updates" vs "update".

Yeah, sorry, I should have been more specific.  On my system:

$ find /var/cache/dnf -iname "*updateinfo*.zck"
/var/cache/dnf/updates-1eb77e9f45b4391a/repodata/0fb800256f5c3558a5a6319b3f647d504a5c1042c1ec3197774d8d5f847a1bbf-updateinfo.xml.zck
/var/cache/dnf/updates-modular-9f12370bbc2f1d95/repodata/11d06a6e7a9943ab7a635829035d160805527bc737b39a1ddffadbc6be1d4fec-updateinfo.xml.zck

zckdl -s <filename> <url> will use <filename> as the source when comparing the chunks with the chunks at <url> so you don't end up downloading the whole file.

If you don't have *anything* in /var/cache/dnf/updates-<hash>, then can you please try just running `zckdl -vvvv http://fedora.ip-connect.info/linux//updates/34/Everything/x86_64/repodata/0fb800256f5c3558a5a6319b3f647d504a5c1042c1ec3197774d8d5f847a1bbf-updateinfo.xml.zck`?

Created attachment 1824386 [details]
Output from zckdl -vvvv <url>

Seems like there were no errors when downloading file this way.

Shouldn't "comp_init" calls be balanced with "comp_close" calls in the output of zckdl? They are not balanced in the output attached.
It seems like we need to somehow hook into libcurl's error handling to get any relevant information at the moment the "Curl error (23): Failed writing received data to disk/application" occurs.

The problem here is that libcurl is using a zchunk callback to process the downloaded data while writing it to the disk, and libcurl isn't passing the zchunk errors on (and, for some reason, we're not seeing them when we have verbose logging on in librepo).

One thing you could try doing is renaming the updateinfo file to old_update_info.zck, changing a few bytes after the half-way mark, and then run `zckdl -vvvv -s old_update_info.zck http://fedora.ip-connect.info/linux//updates/34/Everything/x86_64/repodata/0fb800256f5c3558a5a6319b3f647d504a5c1042c1ec3197774d8d5f847a1bbf-updateinfo.xml.zck`.  This will force zchunk to download new chunks for whatever has changed.  (Or, even better, wait until tomorrow's compose and run `zckdl -vvvv -s 0fb800256f5c3558a5a6319b3f647d504a5c1042c1ec3197774d8d5f847a1bbf-updateinfo.xml.zck http://fedora.ip-connect.info/linux//updates/34/Everything/x86_64/repodata/<new hash>-updateinfo.xml.zck`)

Running zckdl, with or without -s <file> always succeeds.
Jonathan, could you please point where in the source is this zchunk callback and where is it passed to libcurl?
I will ask libcurl people how one could go about getting any more information when such errors occur.

Piotr, before dragging in the libcurl people, I'd really like to verify that the problem is actually with zchunk.  Can you please run the following:

`wget https://www.jdieter.net/downloads/primary-damaged.xml.zck`

Then, run:

`zckdl -v -s primary-damaged.xml.zck https://www.jdieter.net/downloads/primary.xml.zck`

The whole purpose in this exercise is to force a multi-range download from the server.  primary-damaged.xml.zck has five chunks that are invalid, so zckdl will perform a multi-range download to get those five chunks.  If this succeeds, then the problem is most likely *not* with zchunk.  If it fails, we should get detailed enough logs to figure out what the problem is.

When I run the above commands, the last few lines I see are:

```
write_and_verify_chunk: Wrote 775 bytes at 16929975
write_and_verify_chunk: Wrote 1002 bytes at 16930750
write_and_verify_chunk: Wrote 1011 bytes at 16931752
write_and_verify_chunk: Wrote 325 bytes at 16932763
Missing chunks: 5
multipart_get_boundary: Multipart boundary: 00000000000000000005
multipart_extract: Download range: 1093404-1093788
dl_write: Writing 385 bytes
validate_chunk: Chunk 882's checksum: valid
multipart_extract: Download range: 1375381-1376389
dl_write: Writing 1009 bytes
validate_chunk: Chunk 1315's checksum: valid
multipart_extract: Download range: 1879219-1879736
dl_write: Writing 518 bytes
validate_chunk: Chunk 2052's checksum: valid
multipart_extract: Download range: 2346001-2346700
dl_write: Writing 700 bytes
validate_chunk: Chunk 2725's checksum: valid
multipart_extract: Download range: 2660550-2661770
dl_write: Writing 1221 bytes
validate_chunk: Chunk 3263's checksum: valid
Downloaded 527633 bytes
zck_validate_data_checksum: Checking full hash
validate_file: Checking data checksum
validate_file: Expected data checksum:   ab2a618e90408c5939ca8cebc6ab3cd2e21856aabfd7d87d079b04fcd9fa8faf
validate_file: Calculated data checksum: ab2a618e90408c5939ca8cebc6ab3cd2e21856aabfd7d87d079b04fcd9fa8faf
validate_file: Data checksum valid
comp_close: Closing compression
comp_close: Closing compression
```

I'm particularly interested in the multipart_get_boundary and multipart_extract function logging.

Created attachment 1826380 [details]
output from running zckdl on a test file

I attached zckdl-test-file.output.txt file obtained after running the following:

$ wget https://www.jdieter.net/downloads/primary-damaged.xml.zck
$ zckdl -v -s primary-damaged.xml.zck https://www.jdieter.net/downloads/primary.xml.zck 2>&1 | tee zckdl-test-file.output.txt

It looks like the whole file is being downloaded instead of 5 missing chunks you were expecting. Any ideas why this might be the case?

Before running above I installed librepo from comment 13.

Ok, it looks like your proxy is unable to handle range requests, so when a range is requested, it responds with the whole file.  zckdl handles this correctly (by just downloading the whole file), and librepo *should* do the same, but obviously something's broken there.  It would be really helpful to have the HTTP requests and responses so I can see what the proxy is sending, but I think that will take some more hard-coded changes to librepo.  Give me a few days to put something together for you.

Gentle ping.

Sorry, life has been a bit crazy the last few weeks and doesn't look like it's going to slow down any time soon.  The easiest way to get the full HTTP responses would be for you to do the following:

In one terminal, install tcpdump and run `sudo tcpdump -i enp42s0 -s 65535 -w zchunk.pcap host www.jdieter.net and port 80`

In a second terminal, run `zckdl -v -s primary-damaged.xml.zck http://www.jdieter.net/downloads/primary.xml.zck 2>&1 | tee zckdl-test-file.output.txt`

Please verify that it downloaded the full file, and then upload zchunk.pcap.

Sorry, just to clarify, replace `enp42s0` above with whatever interface has internet access.

This message is a reminder that Fedora Linux 34 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 34 on 2022-06-07.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '34'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 34 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

Fedora Linux 34 entered end-of-life (EOL) status on 2022-06-07.

Fedora Linux 34 is no longer maintained, which means that it
will not receive any further security or bug fix updates. As a result we
are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release.

Thank you for reporting this bug and we are sorry it could not be fixed.

Created attachment 1933285 [details]
pcap file requested in comment 28

Created attachment 1933286 [details]
log file from running command requested in comment 28

Jonathan,

I attached the pcap file you requested in comment 28.
All was done from Fedora 37 live image this time.
Could we please reopen this bug?

Hi Piotr,

I'm happy to look into this again.  Unfortunately, due to a web server misconfiguration (or, more accurately, it being configured too well), the command in comment 28 was making a https connection, which we can't inspect in the pcap file.  I've configured the web server to allow that url to be downloaded over http now, so can you please re-run the commands in comment 28.

Also, I can't seem to change the version from 34 to a newer version.  As the reporter, do you see anywhere that you can change the version?

Created attachment 1934421 [details]
pcap file requested in comment 28

Created attachment 1934422 [details]
log file from running command requested in comment 28

(In reply to Jonathan Dieter from comment #35)

> I'm happy to look into this again.

Thank you in advance.

> I've configured the web server to allow that url to be
> downloaded over http now, so can you please re-run the commands in comment
> 28.

Done.

> Also, I can't seem to change the version from 34 to a newer version.  As the
> reporter, do you see anywhere that you can change the version?

No, I don't. I had already been trying to change it but I didn't see any way to do it.
When I tried to change status from CLOSED to ASSIGNED I get the following error
"Version '34' is inactive on product 'Fedora'. You must select an active version."

According to https://bugzilla.redhat.com/show_bug.cgi?id=1028145 I should be able both to reopen and to change version but I don't see how.

Reopening and changing the version to 37.

Jonathan,

Did you have a chance to read my comment 38?


amatej,

Thanks for reopening this.

Yes, and it's clear what the problem is, but I'll need to dig into the librepo code to fix it.  It's going to take some time that I just don't have at the moment.

Jonathan,

Just making sure it's still on your road map :)

Jonathan,

I'm ready to test your fix as soon as you make one :)

Hey man, I've not forgotten, but it will be a while before I have time to fix this. The main issue is that I need to either find a proxy the emulates the behavior you're seeing or need to write one so I can verify that my fix actually works.

If it helps I can test the fix in my environment so that you don't need to find/create proxy.
Could you briefly describe what's the problem with the proxy I'm using that librepo does not handle well?

So the problem here is that when the proxy receives a GET with a range, instead of returning a 206 (Partial content) and the ranges requested, it returns a 200 with the full file.  `zckdl` handles this correctly by just allowing the full file to download, but, when I added zchunk support into librepo I attempted to make it smart enough to switch to the next web server (because I was expecting to see this coming from web servers, not proxies) and only download the full file if we're on the last mirror.  It seems I missed something because it doesn't seem that it's able to download the full file and errors out instead.

It's been several years since I wrote the librepo code, so it's going to take some time for me to get back up to speed on it.  It doesn't help that things are pretty intense at $DAYJOB at the moment, severely limiting the bandwidth I've got for looking into this.

> (…) when I added zchunk support into librepo I attempted to make it smart enough to switch to the next web server (because I was expecting to see this coming from web servers, not proxies) and only download the full file if we're on the last mirror. It seems I missed something because it doesn't seem that it's able to download the full file and errors out instead.

Maybe it's time to revisit this decision and just remove switching logic fixing the error along the way?

This message is a reminder that Fedora Linux 37 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 37 on 2023-12-05.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '37'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version. Note that the version field may be hidden.
Click the "Show advanced fields" button if you do not see it.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 37 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

This message is a reminder that Fedora Linux 39 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 39 on 2024-11-26.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '39'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version. Note that the version field may be hidden.
Click the "Show advanced fields" button if you do not see it.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 39 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

@lnie also uses a proxy server and was able to reproduce this bug on F43, but not any previous Fedora.

*** Bug 2396334 has been marked as a duplicate of this bug. ***

This message is a reminder that Fedora Linux 41 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 41 on 2025-12-15.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '41'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version. Note that the version field may be hidden.
Click the "Show advanced fields" button if you do not see it.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 41 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

Could someone please update Fedora version for this bug to 43 in accordance with comment 51?

For me the same was happening this morning. Here is terminal output:

Updaten en laden van repositories:
 Fedora 42 - x86_64 - Updates                                       100% |  53.3 KiB/s |   4.9 KiB |  00m00s
Downloaden van metadata (metalink: "https://mirrors.fedoraproject.org/metalink?repo=updates-released-f42&arch=x86_64") voor repository "updates": Download failed: Curl error (23): Failed writing received data to disk/application for http://mirror.23m.com/fedora/linux/updates/42/Everything/x86_64/repodata/306261415adc08008482ef186ea9dda3ba9cd7b538f2b17824e9f25713370cc3-primary.xml.zck [Failure writing output to destination, passed 153 returned 0] mislukt

For me "sudo dnf clean all" just fixed the issue, so I am not sure how useful this is to you.

This bug appears to have been reported against 'rawhide' during the Fedora Linux 45 development cycle.
Changing version to 45.