Bug 481115

Summary: libzypp prematurely reacts on aria2c exceptions
Product: [openSUSE] openSUSE 11.2 Reporter: Peter Poeml <poeml>
Component: libzyppAssignee: Duncan Mac-Vicar <dmacvicar>
Status: RESOLVED FIXED QA Contact: E-mail List <qa-bugs>
Severity: Normal    
Priority: P5 - None CC: davejplater
Version: Factory   
Target Milestone: ---   
Hardware: Other   
OS: Other   
Whiteboard:
Found By: --- Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---

Description Peter Poeml 2009-03-02 19:27:42 UTC 
I am testing with X-Broken-Mirrors in .aria2/aria2.conf, which adds
mirror URLs to metalinks that do not work. Updating from Factory, I got
the following:




Overall download size: 10.0 MiB. After the operation, additional 1.7 MiB will be used.
Continue? [YES/no]: y
committing
Retrieving package yast2-trans-stats-2.15.0-120.32.noarch (1/55), 9.0 KiB (1.0 KiB unpacked)
Retrieving: oss [done]
Retrieving: media [done]
Retrieving: yast2-trans-stats-2.15.0-120.32.noarch.rpm [error]
File './suse/noarch/yast2-trans-stats-2.15.0-120.32.noarch.rpm' not found on medium 'http://download.opensuse.org/factory/repo/oss'

Abort, retry, ignore? [A/r/i/?]:




Zypper logs the following:




2009-03-02 20:01:13 <1> linux-7q6o(19775) [zypp++] ExternalProgram.cc(start_program):210 Executing '/usr/bin/aria2c' '--user-agent=ZYpp 6.1.0 (aria2 version 1.2.0) openSUSE-11.2-i586' '--summary-interval=1' '--follow-metalink=mem' '--check-integrity=true' '--header=X-Zypp-AnonymousId: da93627e-e5ca-42ba-8ebc-122fe15c9a8d' '--header=X-ZYpp-DistributionFlavor: ftp' '--connect-timeout=60' '--dir=/var/adm/mount/AP_0x00000001/suse/noarch' 'http://download.opensuse.org/factory/repo/oss/suse/noarch/yast2-trans-stats-2.15.0-120.32.noarch.rpm'
2009-03-02 20:01:13 <1> linux-7q6o(19775) [zypp++] ExternalProgram.cc(start_program):354 pid 19800 launched
2009-03-02 20:01:13 <5> linux-7q6o(19775) [zypp] Exception.cc(log):133 MediaAria2c.cc(getFileCopy):444 THROW:    MediaAria2c.cc(getFileCopy):444: File './suse/noarch/yast2-trans-stats-2.15.0-120.32.noarch.rpm' not found on medium 'http://download.opensuse.org/factory/repo/oss'
2009-03-02 20:01:13 <5> linux-7q6o(19775) [zypp] Exception.cc(log):133
2009-03-02 20:01:13 <5> linux-7q6o(19775) [zypp] Exception.cc(log):133 MediaAria2c.cc(getFileCopy):488 RETHROW:  MediaAria2c.cc(getFileCopy):444: File './suse/noarch/yast2-trans-stats-2.15.0-120.32.noarch.rpm' not found on medium 'http://download.opensuse.org/factory/repo/oss'
2009-03-02 20:01:13 <5> linux-7q6o(19775) [zypp] Exception.cc(log):133
2009-03-02 20:01:13 <5> linux-7q6o(19775) [zypp] Exception.cc(log):133 MediaSetAccess.cc(provideFileInternal):283 CAUGHT:   MediaAria2c.cc(getFileCopy):488: File './suse/noarch/yast2-trans-stats-2.15.0-120.32.noarch.rpm' not found on medium 'http://download.opensuse.org/factory/repo/oss'
2009-03-02 20:01:13 <5> linux-7q6o(19775) [zypp] Exception.cc(log):133
2009-03-02 20:01:13 <1> linux-7q6o(19775) [zypp++] MediaHandler.cc(getDetectedDevices):1387 No devices for this medium
2009-03-02 20:01:13 <1> linux-7q6o(19775) [zypp++] MediaSetAccess.cc(provideFileInternal):293 Media couldn't provide file ./suse/noarch/yast2-trans-stats-2.15.0-120.32.noarch.rpm , releasing.
2009-03-02 20:01:13 <1> linux-7q6o(19775) [zypp++] MediaManager.cc(release):656 release(id=1)
2009-03-02 20:01:13 <1> linux-7q6o(19775) [zypp++] MediaHandler.cc(release):707 Request to release attached media http<http://download.opensuse.org/factory/repo/oss>, use count=1
2009-03-02 20:01:13 <1> linux-7q6o(19775) [zypp++] MediaHandler.cc(release):714 Releasing media http<http://download.opensuse.org/factory/repo/oss>





The aria2.log (which I'm also writing) ends suddenly, which almost looks
as if aria2c was terminated in a manner that it didn't complete its log:




2009-03-02 20:01:42.702789 INFO - CUID#10 - Restarting the download. URI=http://www.poeml.de:83/nonexisting_file_for_libzypp
Exception: Failed to establish connection, cause: Connection refused
2009-03-02 20:01:42.702812 DEBUG - CUID#10 - Unregistering cuid from segmentManager.
2009-03-02 20:01:42.702848 INFO - CUID#10 - 5 times attempted, but no success. Download aborted.
2009-03-02 20:01:42.702867 ERROR - CUID#10 - Download aborted. URI=http://www.poeml.de:83/nonexisting_file_for_libzypp
Exception: Failed to establish connection, cause: Connection refused
2009-03-02 20:01:42.703045 DEBUG - CUID#11 - socket: read:0, write:0, hup:0, err:0
2009-03-02 20:01:42.703206 DEBUG - Attach segment#0 to CUID#11.
2009-03-02 20:01:42.703226 DEBUG - index=0, length=8843, segmentLength=262144, writtenLength=0
2009-03-02 20:01:42.703336 INFO - CUID#11 - Name resolution complete: ftp.opensuse.org -> 195.135.221.134
2009-03-02 20:01:42.703398 INFO - CUID#11 - Connecting to ftp.opensuse.org:21
2009-03-02 20:01:42.719434 DEBUG - CUID#11 - socket: read:0, write:0, hup:1, err:1
2009-03-02 20:01:42.719588 INFO - CUID#11 - Restarting the download. URI=http://ftp.opensuse.org:21/foobar
Exception: Failed to establish connection, cause: Connection refused




The log shows various exceptions that aria2 also prints out to the
terminal (stdout or stderr - not sure).

The thing is that aria2 reports various such errors, but it *does*
handle them in the end. I suspect that libzypp has interrupted aria2c at
some point. It should only interrupt it if the user aborts YaST2 or
presses ctrl-c (zypper receives SIGINT).

The following is a screen log from an aria2 download using a metalink
containing non-working URLs, and it shows how aria2 repeatedly reports
these "Exceptions" for non-working servers. 





root@linux-7q6o:~ # aria2c http://download.opensuse.org/factory/repo/oss/suse/noarch/yast2-trans-stats-2.15.0-120.32.noarch.rpm

2009-03-02 20:18:05.142929 NOTICE - Download complete: ./yast2-trans-stats-2.15.0-120.32.noarch.rpm.metalink

2009-03-02 20:18:05.152324 ERROR - CUID#7 - Download aborted. URI=http://doesnotexist/factory/repo/oss/suse/noarch/yast2-trans-stats-2.15.0-120.32.noarch.rpm
Exception: Failed to resolve the hostname doesnotexist, cause: Name or service not known

2009-03-02 20:18:05.198315 ERROR - CUID#8 - Download aborted. URI=http://www.poeml.de/nonexisting_file_for_libzypp
Exception: Resource not found
[#2 SIZE:0B/8.6KiB(0%) CN:1 SPD:0.00KiB/s]
2009-03-02 20:18:31.311835 ERROR - CUID#9 - Download aborted. URI=http://www.poeml.de:83/nonexisting_file_for_libzypp
Exception: Failed to establish connection, cause: Connection refused
[#2 SIZE:0B/8.6KiB(0%) CN:1 SPD:0.00KiB/s]
2009-03-02 20:19:00.805198 ERROR - CUID#10 - Download aborted. URI=http://ftp.opensuse.org:21/foobar
Exception: Failed to establish connection, cause: Connection refused

2009-03-02 20:19:00.860873 ERROR - CUID#11 - Download aborted. URI=http://download.opensuse.org/error/
Exception: The response status is not successful. status=403
 *** Download Progress Summary as of Mon Mar  2 20:19:05 2009 ***
================================================================================================
[#2 SIZE:0B/8.6KiB(0%) CN:1 SPD:0.00KiB/s]
FILE: ./yast2-trans-stats-2.15.0-120.32.noarch.rpm
------------------------------------------------------------------------------------------------

[#2 SIZE:0B/8.6KiB(0%) CN:1 SPD:0.00KiB/s]
2009-03-02 20:19:27.936226 ERROR - CUID#12 - Download aborted. URI=http://widehat.opensuse.org:22/foobar
Exception: Failed to establish connection, cause: Connection refused

2009-03-02 20:19:28.056165 NOTICE - Download complete: ./yast2-trans-stats-2.15.0-120.32.noarch.rpm

Download Results:
gid|stat|avg speed  |path/URI
===+====+===========+==========================================================
  1|  OK|        n/a|./yast2-trans-stats-2.15.0-120.32.noarch.rpm.metalink
  2|  OK|     106B/s|./yast2-trans-stats-2.15.0-120.32.noarch.rpm

Status Legend:
 (OK):download completed.




These exceptions could actually be very useful.
This could help us to implement an open feature to show accessed mirrors:
https://features.opensuse.org/305320
We don't need to know all accessed mirrors, but only those who give
problems. So it would be best if libzypp ignores the Exceptions and
keeps aria2c running (trust it :) it works :) but actually show them, in
a harmless way. And I will talk to Tatsuhiro whether he can add the
hostname or URL into those exception messages.
Comment 1 Peter Poeml 2009-03-02 19:36:48 UTC 
Sorry, I just noticed that I may be using an oldish libzypp on this
system.

The system is a Virtualbox machine and I had to revert to an older
snapshot today because my newer snapshots were unusable for unknown
reason. This made me time-travel back a bit...

I am going to re-check with newer libzypp.
Comment 2 Peter Poeml 2009-03-02 20:19:18 UTC 
I know a two more things now. First, it occurs with a "not very old"
libzypp-6.1.0:

  root@cherry ~ # rpm -q libzypp --changelog | head
  * Sun Feb 22 2009 ma@suse.de
  - Never refresh repositories from CD/DVD, once they are created. (bnc #476429)
  [...]

That's the current Factory package on powerpc.opensuse.org. The i586 one has
only two further changes:

  * Thu Feb 26 2009 ma@suse.de
  - Use correct default for zconfig(solver.checkSystemFile) (bnc# 475144)
  
  * Thu Feb 26 2009 ma@suse.de
  - Prevent ResStatus from overriding user locks. (bnc #475230)

Unfortunately, all my VirtualBox instances cease to boot when I update
them to newer Factory :( so I'm not sure how to try something out right
now.

But a second thing I noticed is that the sequence of things is different
than I thought: aria2c is not actually killed or terminated. It actually
keeps running, while zypper already shows its "abort/retry" dialogue. I
saw the log scrolling by. In fact, while zypper displays this question,
aria2c continues downloading and eventually succeed in it. thus, libzypp
_assumes_ that aria2c terminated (probably when it sees the exception)
but it isn't the case.
Comment 3 Peter Poeml 2009-03-02 22:07:26 UTC 
Meanwhile, I managed to boot the Factory system again using 11.1 kernel ;( 
and reproduced this bug with the current libzypp. I am observing the
same behaviour there.
Comment 4 Duncan Mac-Vicar 2009-03-03 12:56:06 UTC 
Fixed in upcoming ZYpp 6.2.1
Comment 5 Duncan Mac-Vicar 2009-03-16 10:42:51 UTC 
*** Bug 476430 has been marked as a duplicate of this bug. ***