Bug 963627

Summary:	dnf shows way over 100% in its progress bar
Product:	[Fedora] Fedora	Reporter:	Jan Synacek <jsynacek>
Component:	librepo	Assignee:	Tomas Mlcoch <tmlcoch>
Status:	CLOSED ERRATA	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	akozumpl, tmlcoch, zpavlas
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	hawkey-0.3.13-2.git15db39f.fc19	Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2013-06-07 04:38:06 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Jan Synacek 2013-05-16 09:41:29 UTC

Description of problem:
I spotted this when updating my rawhide machine.

(16/18): python-devel-.7.4-4.fc20.x86_64.rpm                                                        (84%) 64490% [==========================================================================================]  82 kB/s | 184 kB  --:--:-- ETA

Note the "64490%" at the end of the line. However, I don't how to reproduce it, so I'm filing this just for the record.


Version-Release number of selected component (if applicable):
dnf-0.3.3-3.git91ba5e0.fc20.noarch


Steps to Reproduce:
1. dnf update
2.
3.
  
Actual results:
Over 100% in the progress bar.

Expected results:
Progress bar percentage stays in 0-100% range.

Comment 1 Jan Synacek 2013-05-16 10:27:57 UTC

It happened again. I didn't do anything special, just ran dnf update.

dnf seems to be calculating the current progress wrongly as the percentage gets increased by very large numbers.

(33/515): glibc-common-2.17-8.fc20.x86_64.rpm             (7%) 1484705% [==========================================================================================] 153 kB/s | 4.1 MB  --:--:-- ETA 
(33/515): glibc-common-2.17-8.fc20.x86_64.rpm             (7%) 1625990% [==========================================================================================] 148 kB/s | 4.5 MB  --:--:-- ETA 
(33/515): glibc-common-2.17-8.fc20.x86_64.rpm             (7%) 1876134% [==========================================================================================] 129 kB/s | 5.2 MB  --:--:-- ETA 
(33/515): glibc-common-2.17-8.fc20.x86_64.rpm             (7%) 1936817% [==========================================================================================] 128 kB/s | 5.4 MB  --:--:-- ETA 
(33/515): glibc-common-2.17-8.fc20.x86_64.rpm             (7%) 2032706% [==========================================================================================] 133 kB/s | 5.6 MB  --:--:-- ETA 
(33/515): glibc-common-2.17-8.fc20.x86_64.rpm             (7%) 2359370% [==========================================================================================] 200 kB/s | 6.5 MB  --:--:-- ETA

Comment 2 Ales Kozumplik 2013-05-16 10:32:45 UTC

Thanks, apparently there is something odd going on in the librepo vs. progress bar callback interaction in DNF.

Comment 3 Zdeněk Pavlas 2013-05-16 10:40:27 UTC

> --:--:-- ETA 

This means that progress.start() was called without "size" arg set.

> 1484705%

This should contain the per-file progress percentage.  Likely a bug in urlgrabber.progress module (the percentage filed should be empty in this case).  I'll take a look at this.

Comment 4 Zdeněk Pavlas 2013-05-16 13:05:19 UTC

This is a librepo bug.  It's feeding invalid initial "total_to_download" value (about 290, in this case) value to the progress callback.  The "downloaded" value seems to be okay.

>>> import urlgrabber.progress as p
>>> p.text_meter_total_size(100<<30, 7<<30)
>>> m=p.TextMeter()
>>> m.start(text='glibc-common-2.17-8.fc20.x86_64.rpm', size=290)
>>> m.update(4305645)
glibc-common-2.17-8. (7%) 1484705% [==========]  0.0 B/s | 4.1 MB     --:-- ETA 
>>> m.update(4715371)
glibc-common-2.17-8. (7%) 1625990% [==========] 6.7 kB/s | 4.5 MB     --:-- ETA 
...

This reproduces the reported output very closely.  Since downloaded > total_to_download, ETA is negative and not shown.

Comment 5 Fedora Update System 2013-05-27 13:21:34 UTC

hawkey-0.3.13-2.git15db39f.fc19, dnf-0.3.6-1.git24ce938.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/dnf-0.3.6-1.git24ce938.fc19,hawkey-0.3.13-2.git15db39f.fc19

Comment 6 Fedora Update System 2013-05-27 17:03:37 UTC

Package hawkey-0.3.13-2.git15db39f.fc19, dnf-0.3.6-1.git24ce938.fc19:
* should fix your issue,
* was pushed to the Fedora 19 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing hawkey-0.3.13-2.git15db39f.fc19 dnf-0.3.6-1.git24ce938.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-9385/dnf-0.3.6-1.git24ce938.fc19,hawkey-0.3.13-2.git15db39f.fc19
then log in and leave karma (feedback).

Comment 7 Fedora Update System 2013-05-29 17:48:49 UTC

Package hawkey-0.3.13-2.git15db39f.fc19, dnf-0.3.7-1.gitf8bdc98.fc19:
* should fix your issue,
* was pushed to the Fedora 19 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing hawkey-0.3.13-2.git15db39f.fc19 dnf-0.3.7-1.gitf8bdc98.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-9385/hawkey-0.3.13-2.git15db39f.fc19,dnf-0.3.7-1.gitf8bdc98.fc19
then log in and leave karma (feedback).

Comment 8 Fedora Update System 2013-06-07 04:38:06 UTC

hawkey-0.3.13-2.git15db39f.fc19, dnf-0.3.7-1.gitf8bdc98.fc19 has been pushed to the Fedora 19 stable repository.  If problems still persist, please make note of it in this bug report.