Bug 134474

Created attachment 104679 [details]
strace output

strace as requested by svidal

It appears that this is only reproducable using the default yum.conf
pointing to http://download.fedora.redhat.com - the mirrors appear to
be working as expected.

Same problem here.  An strace and the yum.conf attached.

Created attachment 104690 [details]
strace of yum falling over

yum.trace.bz2

Created attachment 104691 [details]
my yum.conf

Created attachment 104692 [details]
uploading my strace correctly this time (I hope)

Created attachment 104693 [details]
uploading my strace correctly this time (I hope)

Created attachment 104694 [details]
uploading my strace correctly this time (I hope)

Furthermore, when I comment out the download.fedora.redhat.com entry,
I get:

[root@localhost ~]# strace -o yum.trace yum --obsoletes update
Setting up Update Process
Setting up Repo:  base
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
base      : ################################################## 3422/3422
Resolving Dependencies
rhythmbox-0.8.7-2.i386.rp 100% |=========================|  33 kB    00:00
gnome-vfs2-devel-2.8.1-5. 100% |=========================| 1.5 kB    00:00
Fedora/RPMS/gnome-vfs2-devel-2.8.1-5.i386.rpm: [Errno -1] Header is
not complete.
Error: failure: Fedora/RPMS/gnome-vfs2-devel-2.8.1-5.i386.rpm from
base: [Errno 256] No more mirrors to try.

Now, the interesting thing is that there actually seems to be NO
gnome-vfs2-devel-2.8.1-5 header at all at
http://redhat.secsup.org/fedora/core/development/i386/headers/.  I
have no clue where its getting that from...

From your trace do you have this file:
//var/cache/yum/development/headers/rpm-python-4.3.2-8.i386.hdr

if so could you attach it?

The reason you're not seeing the .hdr in headers is that it is not
there. headers (the dir) is not used anymore. The header is read
directly from the rpm via http byte-ranges

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

Here's the complete output from trying to update 8 packages using yum

I'll attach any straces you want, but notice how on the sixth run yum
all of a sudden grabs the three remaining headers and then continues
with the install.

Might be worth having a look at the strace yum.6?

[root@localhost ~]# strace -o /tmp/yum.1 yum --obsoletes upgrade
Setting up Upgrade Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
primary.xml.gz            100% |=========================| 925 kB    00:34
developmen: ################################################## 3422/3422
Resolving Dependencies
gettext-0.14.1-11.i386.rp 100% |=========================|  27 kB    00:01
[root@localhost ~]# strace -o /tmp/yum.2 yum --obsoletes upgrade
Setting up Upgrade Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
developmen: ################################################## 3422/3422
Resolving Dependencies
gamin-0.0.14-1.i386.rpm   100% |=========================| 7.1 kB    00:00
[root@localhost ~]# strace -o /tmp/yum.3 yum --obsoletes upgrade
Setting up Upgrade Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
developmen: ################################################## 3422/3422
Resolving Dependencies
howl-devel-0.9.6-6.i386.r 100% |=========================| 7.4 kB    00:00
[root@localhost ~]# strace -o /tmp/yum.4 yum --obsoletes upgrade
Setting up Upgrade Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
developmen: ################################################## 3422/3422
Resolving Dependencies
gamin-devel-0.0.14-1.i386 100% |=========================| 4.4 kB    00:00
[root@localhost ~]# strace -o /tmp/yum.5 yum --obsoletes upgrade
Setting up Upgrade Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
developmen: ################################################## 3422/3422
Resolving Dependencies
authconfig-4.6.5-1.i386.r 100% |=========================|  29 kB    00:01
[root@localhost ~]# strace -o /tmp/yum.6 yum --obsoletes upgrade
Setting up Upgrade Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
developmen: ################################################## 3422/3422
Resolving Dependencies
howl-libs-0.9.6-6.i386.rp 100% |=========================| 3.3 kB    00:00
authconfig-gtk-4.6.5-1.i3 100% |=========================|  22 kB    00:01
howl-0.9.6-6.i386.rpm     100% |=========================| 4.6 kB    00:00

Dependencies Resolved
                [u] authconfig.i386 0:4.6.5-1 - user
                [u] authconfig-gtk.i386 0:4.6.5-1 - user
                [u] gamin.i386 0:0.0.14-1 - user
                [u] gamin-devel.i386 0:0.0.14-1 - user
                [u] gettext.i386 0:0.14.1-11 - user
                [u] howl.i386 0:0.9.6-6 - user
                [u] howl-devel.i386 0:0.9.6-6 - user
                [u] howl-libs.i386 0:0.9.6-6 - user
Is this ok [y/N]: y
gettext-0.14.1-11.i386.rp 100% |=========================| 1.2 MB    00:46
gamin-0.0.14-1.i386.rpm   100% |=========================|  65 kB    00:02
howl-devel-0.9.6-6.i386.r 100% |=========================| 117 kB    00:04
gamin-devel-0.0.14-1.i386 100% |=========================|  16 kB    00:00
authconfig-4.6.5-1.i386.r 100% |=========================| 253 kB    00:09
howl-libs-0.9.6-6.i386.rp 100% |=========================|  88 kB    00:03
authconfig-gtk-4.6.5-1.i3 100% |=========================|  35 kB    00:01
howl-0.9.6-6.i386.rpm     100% |=========================| 104 kB    00:03
Running Transaction Test
Finished Transaction Test
Transaction Test Succeeded
Running Transaction
howl 100 % done 1/16
howl-libs 100 % done 2/16
authconfig 100 % done 3/16
gamin 100 % done 4/16
gettext 100 % done 5/16
howl-devel 100 % done 6/16
gamin-devel 100 % done 7/16
authconfig-gtk 100 % done 8/16
Completing update for gettext  - 9/16
Completing update for gamin  - 10/16
Completing update for howl-devel  - 11/16
Completing update for gamin-devel  - 12/16
Completing update for authconfig  - 13/16
Completing update for howl-libs  - 14/16
Completing update for authconfig-gtk  - 15/16
Completing update for howl  - 16/16
Complete!
[root@localhost ~]#

Yeah... It is a little less broken (for whatever reason) today.
I only had to run yum twice, which is a distinct improvement over this
weekend's festivities.
[root@sw-lt01 ~]# yum -y update
Setting up Update Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
primary.xml.gz            100% |=========================| 925 kB    00:22
developmen: ################################################## 3422/3422
Resolving Dependencies
gettext-0.14.1-11.i386.rp 100% |=========================|  27 kB    00:00
[root@sw-lt01 ~]# yum -y update
Setting up Update Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
developmen: ################################################## 3422/3422
Resolving Dependencies
gamin-0.0.14-1.i386.rpm   100% |=========================| 7.1 kB    00:00
mod_perl-1.99_16-3.i386.r 100% |=========================|  67 kB    00:00
authconfig-4.6.5-1.i386.r 100% |=========================|  29 kB    00:00
howl-libs-0.9.6-6.i386.rp 100% |=========================| 3.3 kB    00:00
HelixPlayer-1.0.1.gold-1. 100% |=========================|  21 kB    00:00
authconfig-gtk-4.6.5-1.i3 100% |=========================|  22 kB    00:00
howl-0.9.6-6.i386.rpm     100% |=========================| 4.6 kB    00:00

Dependencies Resolved
                [u] HelixPlayer.i386 1:1.0.1.gold-1 - user
                [u] authconfig.i386 0:4.6.5-1 - user
                [u] authconfig-gtk.i386 0:4.6.5-1 - user
                [u] gamin.i386 0:0.0.14-1 - user
                [u] gettext.i386 0:0.14.1-11 - user
                [u] howl.i386 0:0.9.6-6 - user
                [u] howl-libs.i386 0:0.9.6-6 - user
                [u] mod_perl.i386 0:1.99_16-3 - user
gettext-0.14.1-11.i386.rp 100% |=========================| 1.2 MB    00:14
gamin-0.0.14-1.i386.rpm   100% |=========================|  65 kB    00:01
mod_perl-1.99_16-3.i386.r 100% |=========================| 1.4 MB    02:21
authconfig-4.6.5-1.i386.r 100% |=========================| 253 kB    00:04
howl-libs-0.9.6-6.i386.rp 100% |=========================|  88 kB    00:00
HelixPlayer-1.0.1.gold-1. 100% |=========================| 3.6 MB    00:49
authconfig-gtk-4.6.5-1.i3 100% |=========================|  35 kB    00:00
howl-0.9.6-6.i386.rpm     100% |=========================| 104 kB    00:01
Running Transaction Test
Finished Transaction Test
Transaction Test Succeeded
<snip>
Complete!
[root@sw-lt01 ~]#

so, since I couldn't find anything in yum or in python that exited
with errorcode 127 I started looking through rpm.

rpm 4.3.2-8 - added oct 1st:
rpmdb/legacy.c line 132:

            _exit(127);

this is inside the 'open_dso' function.

I think that is a winner. Jeff, do you know what this function does
and why it would be exiting with 127 and not raising an rpm error?

Can we get straces run with:

strace -fF -s 7000

And also compressed attachments of 

tcpdump -s 0 -w yum.tcpdump host download.fedora.redhat.com

whilst running a single failing update.

Created attachment 104822 [details]
yum tcdump

Reproduced using yum 2.1.5. Added some extra verbosity courtesy of
Seth. tcpdump attached above, strace attached below.

Console output:

[root@dhcp-210 ~]# yum clean all
D: opening  db environment /var/lib/rpm/Packages joinenv
D: opening  db index       /var/lib/rpm/Packages rdonly mode=0x0
D: locked   db index       /var/lib/rpm/Packages
D: opening  db index       /var/lib/rpm/Providename rdonly mode=0x0
D: closed   db index       /var/lib/rpm/Providename
D: closed   db index       /var/lib/rpm/Packages
D: closed   db environment /var/lib/rpm/Packages
Cleaning up Packages and Headers
1 headers removed
0 packages removed
[root@dhcp-210 ~]# strace  -fF -s 7000  -o foo3.txt yum update
D: opening  db environment /var/lib/rpm/Packages joinenv
D: opening  db index       /var/lib/rpm/Packages rdonly mode=0x0
D: locked   db index       /var/lib/rpm/Packages
D: opening  db index       /var/lib/rpm/Providename rdonly mode=0x0
D: closed   db index       /var/lib/rpm/Providename
D: closed   db index       /var/lib/rpm/Packages
D: closed   db environment /var/lib/rpm/Packages
Setting up Update Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
developmen: ################################################## 3423/3423
D: opening  db environment /var/lib/rpm/Packages joinenv
D: opening  db index       /var/lib/rpm/Packages rdonly mode=0x0
Resolving Dependencies
usermode-1.73-1.i386.rpm  100% |=========================|  26 kB    00:01
D: opening  db environment /var/lib/rpm/Packages joinenv
D: opening  db index       /var/lib/rpm/Packages rdonly mode=0x0
D: Exiting on signal ...
D: closed   db index       /var/lib/rpm/Packages
D: closed   db environment /var/lib/rpm/Packages
D: closed   db index       /var/lib/rpm/Packages
D: closed   db environment /var/lib/rpm/Packages

Woops, too big for a bugzilla attachment, so find the strace output here:

http://people.redhat.com/rkearey/foo3.txt.gz

This is almost certainly SIGPIPE from the http transfer
being delivered to the rpmlib, rather than the python,
signal handler.

rpmlib traps SIGPIPE so that the command
    rpm -qa | less
does not leave stale rpmdb locks.

The problem is just starting to show up because yum
now adds just parsed headers to a transaction set,
which opens the rpmdb, which sets a SIGPIPE handler,
and so the next http: request from the server,
which can fail with SIGPIPE delivery, causes immediate exit.

The easiest fix is separate signal handling domains
for urlGrabber and rpmlib.

The alternative fix, having cooperative signal handlers
between rpmlib and yum, is possible, but a whole lot of
trouble for not much gain.

skvidal has details as well.

It seems like up2date, once it starts using the xml metadata is going
to have the same problem. If rpmlib grabs SIGPIPE and exits then
up2date is going to exit just as much.

rpmlib ain't exactly grabbing SIGPIPE, nor does xml metadata
or up2date have anything to do with how yum is implemented,
which is why yum is terminating.

Choosing to implement separate signal handling domains,
by processing all the downloads, and then creating
transactions is one approach that would work for other
applications, just as it would work for yum.

There are other, more compilcated, solutions as well.

yum nor urlgrabber implement a signal handler.

So if there is a signal handler in play it's in python and then
up2date and anaconda would fall victim to them as well.

This is the order of events that I'm seeing:
- yum begins
- imports rpm module
- opens a transaction set
- downloads some files to pack into the transaction set
  urlgrabber uses keepalives to make the downloads faster/more efficient
-at some point while yum is depsolving the web server the repository is  
 on closes the keepalive that is left around.
- this means the process is sent a SIGPIPE b/c of the keepalive going
away.
- rpmlib has intercepted sigpipe and exits.

That's what appears to be happening. If anyone else can explain this
to me as to what is happening I'd like to hear it b/c I'm not sure how
I can work around this in yum short of closing everything up and
terminating the transaction set for each download, to insure that rpm
doesn't ever receive a sigpipe.

For those people who can replicate this bug.
Please try the following:
keepalive=0
in each repository section
so:
[development]
name=Fedora Core Development (Rawhide)
baseurl=somewhere
keepalive=0

Then see if it comes back
Thanks

skvidal you rock- yum is working as it should be for me.

It also work for me but yum doesn't seems to work better anyway : yum
doesn't exit silently anymore but at some point, it hangs while
downloading headers. Don't know if it's linked to this bug or if this
is an other bug.

fun with sigpipes
rpm -qa|grep openoffice
openoffice-*1.1.2-8 is installed
 
rpm -Uvh openoffice-*1.1.2-9.i386.rpm
wait till after the preparing hash is done
kill -13 `/sbin/pidof rpm`
watch rpm exit after it completes the first package hashbar

rpm -qa|grep openoffice
notice duplicates 1.1.2-8 and 1.1.2-9

rpm -V  against a 1.1.2-8 duplicate
be utterly underwhelmed by the -V output.

I have to wonder, is this really the behavior one would expect when
rpm process gets a sigpipe as currently handled? Is what I'm seeing a
direct result of the signal handling as mentioned in comment 19? Is
preventing stale locks in the db worth the database corruption I'm seeing?

-jef

In response to comment #26:
 Thierry stop using the primary site - use a mirror and see if the
hangs get better. The hangs occur b/c the site is overloaded, a lot.

seth: Yes, creating a socket object does
    signal(SIGPIPE, SIG_IGNORE);
That is a very stupid thing for python to do imho, working
with misa at better.

jef: I've implemented exactly what I intended to implement
in rpmlib. Yes, a signal handler in a library, and the condvar
to guarantee delivery of SIGCHLD to a thread, are unusual
but absolutely necessary imho.

rpm leaving the database in disarray upon exceptional exit
from a upgrade in progress is up to the sysadmin to fix after
the fact. That has always been the way rpm has behaved, and has
nothing whatsoever to do with SIGPIPE handling.

rpm-4.3.2-11 has a pre-emptive wham-bam slam dunk "fix".

This bug report can be closed upon first WORKSFORME confirmation.

After an (manual) upgrade of the rpm packages to version rpm*-4.3.2-10
yum ends up wiht a slightly different message:

yum update
Setting up Update Process
Setting up Repo:  development
repomd.xml                100% |=========================| 1.1 kB    00:00
Reading repository metadata in from local files
developmen: ################################################## 3427/3427
Resolving Dependencies
glibc-devel-2.3.3-66.i386 100% |=========================|  75 kB    00:01
Exiting on signal(0x1000) ...

Setting keepalive=0 in yum.conf solves the problem even when using the
primary site.

manually upgraded to rpm*-4.3.2-11 and removed keepalive=0 from yum.conf
WORKSFORME using the kernel.org mirror. The primary site was
uncooperative this AM so I could not test there.

The line 
    Exiting on signal(0x1000)
confirms the exit as SIGPIPE (as in (1 << SIGPIPE)).

There are dueling signal handlers between python and rpmlib.

The python behavior sets
    signal(SIGPIPE, SIG_IGN)
This is an accident waiting to happen, blindly setting
SIG_IGN as a side effect of socket object creation.

Yes, the signal handler in rpm is perhaps a surprise waiting to
happen. Note carefully that rpmlib is doing exactly what
was intended with the signal handler, cleaning up the rpmdb
locks and gracefully exiting without leaving stale locks.

The SIGPIPE SIG_IGN signal handler is now honored by rpmlib
iff SIG_IGN is set when the rpmlib signal handler is first set.

So rpmlib perhaps will behave correctly if yum first undertakes a
socket creation, and then searches using a ts.dbMatch() iterator
(which will trigger a rpmdb open which will set a new signal handler
which will honor SIG_IGN if currently set).

No matter what, this is an application (i.e. yum) issue to solve,
even though both python and rpmlib are where the signal handler's
are instantiated.

WORKSFORME from the primary site as well FWIW- can this be closed?
Unclear if this particular issue is resolved after comment #33.

Well... This bug is alive, kicking & well with my fresh fc3 T3
install- the keepalive=0 thing fixes it, seems fc3 t3 shipped
w/rpm-4.3.2-8. Since rpm-4.3.2.11 is on the list of stuff to upgrade
post install I'm hopeful that everything will work OK (crossing fingers)

don't upgrade to rpm 4.3.2-11 - yum will not function for dep
resolution after that.

And fc3t3 - fresh install is an older version of yum.

You might want to upgrade that first.

Did rpm-4.3.2-12 fix the issue? Upgraded to rpm-4.3.2-12 and then did
yum update tonight & things workedforme.
...Just wondering if this is resolved & can be closed.

Works fine in FC3 T3 w/ yum 2.1.7-2 + rpm*-4.3.2.12 so closing