Bug 218207

I had the problem when I was only updating selinux-policy.

This isn't really a yum problem (nor a selinux-policy problem).  There are
probably two reaons:

1. It's a kernel problem.  Loading a new policy somehow screws up the current
state of the system.

2. It's a problem of X which cannot understand some system events created when a
new policy is loaded.

Ideally the kernel should keep all this from happening but there are certainly
some policy changes which require running apps to be notified.  But I know that
the policy I updated only had a minor change which did not affect X or yum.

Somebody should make a call as to whether this is a kernel or X problem.  I
would start with the kernel.

It happened to me, too, but the duplicate packages list is much larger (I
haven't updated in a while). It surely isn't a yum issue, because I don't use
yum ;) Anyhow, what I'd like to see here is a workaround, like a script to
detect and remove duplicate packages excluding kernels and kmods. Maybe there is
something like that available in a Fedora package?

(In reply to comment #2)

> yum ;) Anyhow, what I'd like to see here is a workaround, like a script to
> detect and remove duplicate packages excluding kernels and kmods. Maybe there is
> something like that available in a Fedora package?
Yeah, it's called smart. It tries to 'smartly' remove duplicates. I've had this
x-session terminates during update issue too, and smart did help in cleaning up
the duplicates left behind.

Just a metoo, and the last package that was installed was
selinux-policy-targeted, so I guess that confirms Ulrich's comment.

(In reply to comment #4)
> Just a metoo, and the last package that was installed was
> selinux-policy-targeted, so I guess that confirms Ulrich's comment.

Does it matter if selinux is enabled or not?

This problem is pretty bad, makes Fedora look terrible.

Anyway, check out Seth Vidal's blog:

http://skvidal.wordpress.com/2006/12/04/re-wow/

After running this python script, I then had to delete the contents of /tmp
before I was able to log in to Gnome again.

-EMETOO.  Happened in a RHEL update as well.

I had this problem on three machines.  On one of i686 machines, I just needed to
log back in.  On the second i686, I had to clear /tmp because of dozens of
errors at login.  On the AMD64, the rpm database was corrupted (all rpm commands
hung) and I had to run a rebuilddb.

If there's any additional recovery needed from this, could someone lay it out? 
X86_64 machines typically have many duplicate packages (multilib), so how should
these be detected and corrected?

I sort of doubt this is an X issue.  The only selinux-awareness in X is to avoid
the codegen dispatch paths in GLX when the selinux policy would prevent it.  If
selinux is sending me events just for calling is_selinux_enabled and
selinux_get_boolean_*, then that's pretty broken.

Created attachment 142766 [details]
Diff between old and new policy.

This is not happening everywhere.  I have not found a machine here that can
reproduce.

I just wanted to note that the update just hit my ppc (Powerbook) machine, and
the same thing happened there.  It's hit my i686, x86_64 and ppc architecture
machines, so it's certainly not architecture specific.

I had auditing rules loaded and captured this at the critical time:

type=PATH msg=audit(12/01/2006 10:47:54.912:42720) : item=0
name=/usr/share/selinux/targeted/smartmon.pp inode=1658329 dev=08:02 mode=f
ile,644 ouid=root ogid=root rdev=00:00 obj=system_u:object_r:usr_t:s0 
type=CWD msg=audit(12/01/2006 10:47:54.912:42720) :  cwd=/home/sgrubb 
type=SYSCALL msg=audit(12/01/2006 10:47:54.912:42720) : arch=i386
syscall=lsetxattr success=yes exit=0 a0=d306940 a1=4dc9100b a2=d306be
8 a3=1b items=1 ppid=7878 pid=7881 auid=sgrubb uid=root gid=root euid=root
suid=root fsuid=root egid=root sgid=root fsgid=root tty=(non
e) comm=pup exe=/usr/bin/python subj=system_u:system_r:rpm_t:s0 key=(null) 
----
type=SYSCALL msg=audit(12/01/2006 10:48:03.780:42721) : arch=i386 syscall=write
success=yes exit=1014939 a0=4 a1=b7de3000 a2=f7c9b a3=b
fd0e288 items=0 ppid=11032 pid=11034 auid=sgrubb uid=root gid=root euid=root
suid=root fsuid=root egid=root sgid=root fsgid=root tty=(n
one) comm=load_policy exe=/usr/sbin/load_policy
subj=system_u:system_r:load_policy_t:s0 key=(null) 
type=MAC_POLICY_LOAD msg=audit(12/01/2006 10:48:03.780:42721) : policy loaded
auid=sgrubb 
----
type=USER_END msg=audit(12/01/2006 10:48:05.796:42722) : user pid=2286 uid=root
auid=sgrubb subj=system_u:system_r:xdm_t:s0-s0:c0.c1023
 msg='PAM: session close acct=sgrubb : exe=/usr/sbin/gdm-binary (hostname=?,
addr=?, terminal=:0 res=success)' 
----
type=PATH msg=audit(12/01/2006 10:48:05.796:42723) : item=0
name=/etc/security/pam_env.conf inode=1561719 dev=08:02 mode=file,644 ouid=
root ogid=root rdev=00:00 obj=system_u:object_r:etc_t:s0 
type=CWD msg=audit(12/01/2006 10:48:05.796:42723) :  cwd=/var/gdm 
type=SYSCALL msg=audit(12/01/2006 10:48:05.796:42723) : arch=i386 syscall=open
success=yes exit=9 a0=4300d9 a1=8000 a2=1b6 a3=844c598 i
tems=1 ppid=2195 pid=2286 auid=sgrubb uid=root gid=sgrubb euid=root suid=sgrubb
fsuid=root egid=root sgid=sgrubb fsgid=root tty=(none) 
comm=gdm-binary exe=/usr/sbin/gdm-binary
subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 key=(null)

It was chugging along writing the .pp files. Then it did a policy load. Then my
pam session ended. Then gdm was busy loading pam config files and other such things.

More info from /var/log/messages:

Dec  1 10:47:27 discovery Updated: system-config-printer.i386 0.7.32.2-1.el5
Dec  1 10:47:34 discovery auditd[1783]: dispatch err (pipe full) event lost
Dec  1 10:47:34 discovery last message repeated 9 times
Dec  1 10:47:34 discovery auditd[1783]: dispatch error reporting limit reached -
ending report notification.
Dec  1 10:47:54 discovery Updated: selinux-policy-strict.noarch 2.4.4-2.el5
Dec  1 10:48:03 discovery kernel: security:  3 users, 6 roles, 1572 types, 170
bools, 1 sens, 1024 cats
Dec  1 10:48:03 discovery kernel: security:  59 classes, 48779 rules
Dec  1 10:48:03 discovery dbus: Can't send to audit system: USER_AVC avc: 
received policyload notice (seqno=2) : exe="?" (sauid=81, hostname=?, addr=?,
terminal=?)
Dec  1 10:48:03 discovery dbus: Can't send to audit system: USER_AVC avc: 
received policyload notice (seqno=2) : exe="/bin/dbus-daemon" (sauid=4325,
hostname=?, addr=?, terminal=?)
Dec  1 10:48:06 discovery auditd[1783]: dispatch err (pipe full) event lost
Dec  1 10:48:06 discovery last message repeated 5 times
Dec  1 10:48:07 discovery gpm[1968]: *** info [mice.c(1766)]:
Dec  1 10:48:07 discovery gpm[1968]: imps2: Auto-detected intellimouse PS/2
Dec  1 11:02:06 discovery gconfd (sgrubb-11235): starting (version 2.14.0), pid
11235 user 'sgrubb'

It did a policy reload on strict policy which I don't use. Looks like gdm is
re-reading its config after that.

Steve, can you add Enable=true to the [debug] section of /etc/gdm/custom.conf so
we can get some more gdm spew to see what it's take on things is?

I've updated another system and deliberately left out selinux-policy-*.  This
system's X session also crashed.  The last package which got installed is
policycoreutils.  The message after that is exactly what Steve described.  audit
messages are not getting through.

So it is not the latest policy's fault (in any case would it be the kernel's
problem to react to the changed policy this way).

Same issue here :

Dec  5 10:14:22 localhost Updated: autofs.x86_64 1:5.0.1-0.rc2.25
Dec  5 10:14:22 localhost Updated: ypbind.x86_64 3:1.19-6.fc6
Dec  5 10:14:24 localhost Updated: evolution-connector.x86_64 2.8.2-2.fc6
Dec  5 10:14:31 localhost kernel: security:  3 users, 6 roles, 1577 types, 170
bools, 1 sens, 1024 cats
Dec  5 10:14:31 localhost kernel: security:  59 classes, 49211 rules
Dec  5 10:14:31 localhost dbus: Can't send to audit system: USER_AVC avc: 
received policyload notice (seqno=2) : exe="/bin/dbus-daemon" (sauid=500,
hostname=?, addr=?, terminal=?)
Dec  5 10:14:31 localhost dbus: Can't send to audit system: USER_AVC avc: 
received policyload notice (seqno=2) : exe="?" (sauid=81, hostname=?, addr=?,
terminal=?)
Dec  5 10:14:33 localhost restorecond: Will not restore a file with more than
one hard link (/etc/resolv.conf) Invalid argument
Dec  5 10:14:33 localhost kernel: npviewer.bin[11235]: segfault at
00000000f5bfc030 rip 00000000f7e53300 rsp 00000000f5bf019c error 4
Dec  5 10:14:40 localhost Updated: selinux-policy-targeted.noarch 2.4.6-1.fc6
Dec  5 10:16:13 localhost Updated: libsepol-devel.x86_64 1.15.3-1.fc6
Dec  5 10:16:14 localhost Updated: paps.x86_64 0.6.6-17.fc6
Dec  5 10:17:02 localhost shutdown[18598]: shutting down for system reboot
Dec  5 10:17:02 localhost init: Switching to runlevel: 6 
Dec  5 10:17:03 localhost restorecond: Will not restore a file with more than
one hard link (/etc/resolv.conf) No such file or directory 
Dec  5 10:17:03 localhost avahi-daemon[2331]: Got SIGTERM, quitting.
Dec  5 10:17:03 localhost avahi-daemon[2331]: Leaving mDNS multicast group on
interface eth0.IPv6 with address fe80::213:72ff:fedc:c81d.
Dec  5 10:17:03 localhost avahi-daemon[2331]: Leaving mDNS multicast group on
interface eth0.IPv4 with address 10.0.2.19.
Dec  5 10:17:05 localhost smartd[2454]: smartd received signal 15: Terminated
Dec  5 10:17:05 localhost smartd[2454]: smartd is exiting (exit status 0)  
Dec  5 10:17:09 localhost rpc.statd[2025]: Caught signal 15, un-registering and
exiting.
Dec  5 10:17:09 localhost portmap[18994]: connect from 127.0.0.1 to
unset(status): request from unprivileged port 
Dec  5 10:17:10 localhost auditd[3359]: The audit daemon is exiting.
Dec  5 10:17:10 localhost kernel: audit(1165281430.280:1228): audit_pid=0
old=3359 by auid=500 subj=user_u:system_r:auditd_t:s0
Dec  5 10:17:10 localhost kernel: Kernel logging (proc) stopped.
Dec  5 10:17:10 localhost kernel: Kernel log daemon terminating.
Dec  5 10:17:11 localhost exiting on signal 15
Dec  5 10:19:01 localhost syslogd 1.4.1: restart.

Can someone who has seen this please attach an X log file generated while this
was happening?

I have reproduced this with gdb attached to the X server. From the X server's
point of view, it just looks like all clients disappear (a sequence of
SIGPIPE's). Then the X server exits normally.

So I don't think there's any X problem here.

You didn't by any chance do what I mentioned in comment 15 ? If so, did the gdm
messages in /var/log/messages show anything interesting?

Sorry, I didn't. But I did reproduce it again, with gdb attached to
gnome-session and various gdm-binary processes. gnome-session terminates with
SIGHUP, and one of the gdm-binary processes gets SIGUSR2, another SIGUSR1.

well, one of the gdm-binary processes sends SIGUSR2 to one of the other
gdm-binary processes as part of normal communication.

Also, one of the gdm-binary processes will wait for SIGUSR1 from the X server at
start up (to know when the X server is ready for connections to display the
greeter), but I don't believe it uses that signal at any other point.

It could very well be the hangup signal gnome-session is getting, is causing it
to exit and take the session down with it and the other signals you saw were
part of gdm's normal reinitialization.

I'd still like to see a log, btw, if anyone is willing to help?

Otherwise, i'll try to reproduce the problem soon and get the logs that way.

I've put that setting in but this evening's updates didn't trigger the crash. 
Gaim crashed, though I'm not sure whether that was related to the updates going
on at the time.

(In reply to comment #23)
> I'd still like to see a log, btw, if anyone is willing to help?
> 

I did what you said in comment #15. More precisely:

1. I reinstalled FC6 in the the same Toshiba laptop
2. I edited "/etc/gdm/custom.conf" to read:
[debug]
Enable=true

3. I run "yum update yum" then "yum update"

4. crash happened, but gdm.log does not seems to have anything useful.

I am not 100% sure if what you want is the latest or the .1 log, so I am going
to attach both of them

Created attachment 143239 [details]
/var/log/messages file

I found more info about the crash on the attached /var/log/messages.

I hope it can help to nail it down

Hi Gianluca,
Thanks for the syslog output.

> Dec 10 12:01:18 tosco Updated: gnome-bluetooth.i386 0.7.0-11.fc6
> Dec 10 12:01:27 tosco kernel: security:  3 users, 6 roles, 1577 types, 170
bools, 1 sens, 1024 cats
> Dec 10 12:01:27 tosco kernel: security:  59 classes, 49211 rules
> Dec 10 12:01:27 tosco dbus: Can't send to audit system: USER_AVC avc: 
received policyload notice (seqno=2) : exe="/bin/dbus-daemon" (sauid=500,
hostname=?, addr=?, terminal=?)
> Dec 10 12:01:27 tosco dbus: Can't send to audit system: USER_AVC avc: 
received policyload notice (seqno=2) : exe="?" (sauid=81, hostname=?, addr=?,
terminal=?)
> Dec 10 12:01:27 tosco kernel: audit(1165748487.858:6): policy loaded
auid=4294967295
> Dec 10 12:01:27 tosco gdm[2741]: slave_waitpid: done_waiting
> Dec 10 12:01:27 tosco gdm[2741]: Session: start_time: 1165747019 end_time:
1165748487
> Dec 10 12:01:27 tosco gdm[2741]: session '2810' exited with status '1',
recording logout
> Dec 10 12:01:27 tosco gdm[2741]: writing logout record
...
> Dec 10 12:01:29 tosco Updated: selinux-policy-targeted.noarch 2.4.6-1.fc6
So the above bits seem the most relevant.  gnome-session isn't
dying from a hangup signal, it's exiting with an abnormal exit
status.  Note after a successful login, gnome-session will never
exit with status 1 on it's own, but I guess a library it's
linked to might.  

By default xlib will call exit(1) when it get
an unhandled error (such as the X server getting killed, or for a
bunch of other arbitrary reasons). So one theory may be that X
is dying first and that's why gnome-session is going away.

As mentioned before, the "Can't send to audit system" error
seems pretty suspect.  Could it it be that the X server uses audit libs and
sends an exception to clients if it can't write to the audit
system?

Adam, do you know?

The message that you are seeing from dbus is where its trying to log a policy
reload message to the audit system and for whatever reason does not have the
capabilities. The audit system does not kill the program (dbus) it just sends
back a failure error code. The dbus code never checks the return code. So, I
would find it unlikely for the audit system to be causing this.

I also wonder what was the cause of the program dying in comment #16 where
selinux policy was left out of the update? Without SE Linux policy update, no
reload should occur and no write to the audit system.

Note, I wasn't saying that the audit system would kill the program, or that dbus
was involved at all.

I was just asking Adam if

1) the X server links against and uses the audit libraries
2) if yes to 1), then if it every encountered a failure logging to the audit
libs would it throw an exception to clients that they subsquently might fail to
handle.

It seems kind of like a long shot, but I was just checking.

It just occurred to me, that if xlib is calling exit(1) we will probably get a
message in ~/.xsession-errors.

Gianluca, can you (or anyone) post your .xsession-errors file?

(In reply to comment #27)
> As mentioned before, the "Can't send to audit system" error
> seems pretty suspect.  Could it it be that the X server uses audit libs and
> sends an exception to clients if it can't write to the audit
> system?
> 
> Adam, do you know?

It does not.

Created attachment 143547 [details]
xorg-x11-server-1.1.1-watch-for-evil-hangups.patch

I'm trying an update now with an X server patched with the above patch.  This
should hopefully tell us which process is causing the issue.

Soeren, Adam, and I spent a while debugging this today and we figured out that
this is caused by the running session dbus-daemon getting told to reload its
config file during the update.  It rereads the config file from disk, but at
this point the config file has been updated to the version from the new dbus
package.  the config file that ships with the new dbus package isn't compatible
with the running dbus, so the running dbus-daemon exits and brings the session
down with it.

So I wonder if we could work around this problem by adding a prereq on
selinux-policy-targeted (or maybe a conflicts: selinux-policy-targeted <
the-current-version) to force package ordering the transaction such that dbus
gets the policyload notice and reloads itself before it gets upgraded and has
the incompatible config file on disk.

I'm going to push the conflicts option into updates-testing today. If it works
i'll push it out to final.  If it doesn't work, i'll push out another update to
updates-testing adding the less desirable prereq.

Okay, I've built dbus-1.0.1-3.fc6 with the conflicts field added.

It should be showing up into updates-testing shortly.  If anyone wants to
confirm that it fixes the problem that would be great.  I'll start a fresh fc6
install now to see, also.

the conflicts field wasn't sufficient to ensure the right ordering, so I'm going
to build with the prereq.

So the PreReq fix, does solve the problem on the surface, but it's not really
adequate in general.

Dan pointed out to me that some users frequently do multiple update transactions
without ever logging out.  In that case, the PreReq trick wouldn't be sufficient
for the second update transaction.

One solution we're looking at now is moving the config file to a new location
and always shipping the old config file in the old place for backward compatibility.

Created attachment 143792 [details]
move config file

So I just built the above patch into dbus-1.0.1-5.fc6

It moves the bus daemon policy files to /usr/share/dbus-1 (where they problably
should have been from the start) and keeps the backward compatible policy files
in /etc/dbus-1

This patch also keeps dbus from dying on SIGHUP when it encounters an unknown
config option in the future.

I'll do some testing today to see if dbus-1.0.1-5.fc6 works okay.

Okay, i've tested dbus-1.0.1-5.fc6 and it seems to work

I would appreciate if someone else can enable -updates-testing and verify that
it fixes the problem.

Assuming I don't hear any complications, I'll push this to -updates soon.

Hi guys,

There is currently some ongoing discussion on the upstream dbus mailing list
about the solution posted in attachment 143792 [details] (comment 40).

The thread is available here:
http://lists.freedesktop.org/archives/dbus/2006-December/006666.html

Until we've figured out what the best way to go is, I'm going to hold off on
moving the fix from -updates-testing to -updates.

Note there may be a separate dbus update before the discussion is resolved to
address an unrelated denial of service security issue (bug 219665).

Ray: I had my machine perform some tests with the dbus-1.0.1-5.fc6 from -testing.
The machine tested is an fc6 + kernel +yum updated vmware virtual machine. After
each test the original virtual machine was copied over the test vm, so I started
again from same non-updated position.
$ uname -a
Linux eng 2.6.18-1.2849.fc6 #1 SMP Fri Nov 10 12:45:28 EST 2006 i686 athlon i386
GNU/Linux
===
With the -updates, pup with 101 updates: the upgrade dropped login prompt:text,
and then started up the gdm login screen. After login, there was a black screen,
which then popped up the puplet updates available note, with about 50 updates
done. After updated completed, and close pup, the desktop was just black.
ctrl-alt-backspace reverted to gdm login, but again desktop was black.
===
With just dbus update selected {thanks for ctrl-a select all in pup}: the single
update goes through fine.
===
With just dbus and selinux-policy, the original issue occurred.
log for above test:
Oct 03 19:58:47 Erased: xorg-x11-drv-voodoo
Dec 13 06:10:27 Updated: yum.noarch 3.0.1-2.fc6
Dec 13 06:10:31 Updated: pirut.noarch 1.2.8-1.fc6
Dec 13 06:10:32 Updated: yum-updatesd.noarch 3.0.1-2.fc6
Dec 16 15:13:24 Updated: dbus.i386 1.0.1-2.fc6
Dec 16 15:13:30 Updated: selinux-policy.noarch 2.4.6-1.fc6
Dec 16 15:13:31 Updated: dbus-x11.i386 1.0.1-2.fc6
===
With just dbus and selinux-policy but with -testing repo enabled, issue did not
occur. Updating the other 99 or so updates also did not cause the issue to
occur. firefox and openoffice-calc operated OK.
from /var/log/message in case the selinux messages are worthwhile:
Dec 16 16:00:21 eng Updated: dbus.i386 1.0.1-5.fc6
Dec 16 16:00:26 eng Updated: selinux-policy.noarch 2.4.6-7.fc6
Dec 16 16:00:27 eng Updated: dbus-x11.i386 1.0.1-5.fc6
Dec 16 16:00:46 eng kernel: security:  3 users, 6 roles, 1580 types, 170 bools,
1 sens, 1024 cats
Dec 16 16:00:46 eng kernel: security:  59 classes, 49346 rules
Dec 16 16:00:46 eng kernel: security:  invalidating context
system_u:object_r:anacron_exec_t:s0
Dec 16 16:00:46 eng kernel: audit(1166245246.887:4): policy loaded auid=4294967295
Dec 16 16:00:46 eng dbus: Can't send to audit system: USER_AVC avc:  received
policyload notice (seqno=2) : exe="?" (sauid=81, hostname=?, addr=?, terminal=?)
Dec 16 16:00:46 eng dbus: Can't send to audit system: USER_AVC avc:  received
policyload notice (seqno=2) : exe="/bin/dbus-daemon" (sauid=500, hostname=?,
addr=?, terminal=?)
Dec 16 16:03:36 eng Updated: selinux-policy-targeted.noarch 2.4.6-7.fc6
===
With all updates and -testing repo enabled, issue did not occur. firefox and
openoffice-calc operated fine. After the suggested reboot firefox and -calc are
fine, and nothing seen during some short tests.

Summary: No faults seen with the -testing repo enabled. Looks good even
considering your later dbus note.

Hi David,

Thanks for testing the fix.  There's been a little upstream resistence with us
moving the config file to /usr/share/dbus-1.  Apparently, there are some
legitimate cases where admins would want to change the config file.

So what I'm going to do now is ship a backward compatible config file and do an
upgrade on reboot (assuming it has't been modified by the sysadmin before the
reboot)

Okay guys, I've built a fix that should be showing up in -updates-testing
shortly as dbus-1.0.1-9.fc6

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

A colleague of mine just ran into this bug when updateing from only
updates-proper some minutes ago :-/

(In reply to comment #45)
> Okay guys, I've built a fix that should be showing up in -updates-testing
> shortly as dbus-1.0.1-9.fc6

When will that get moved to final? It's running fine for me on two machines. But
I did not check if it fixes the X restart issue...

I have to (or someone) has to confirm that the fix works.  I just got back from
vacation today, so I'll be able to test it tomorrow.  If someone can test it in
the mean time though I can try to move it to final today.

Well, I installed dbus-1.0.1-9.fc6 a week or so back, but have had a number of
occurrences of yumex and yum just dying during update runs since then. It
doesn't kill my X session though, so is this the same bug? I suppose it could be
yumex or something in python.

This is hard to debug, but the machine running it is a laptop and it's been
rebooted lots of times in between tests. I have found it beneficial to do an rm
-f /var/lib/rpm/__db00? before running yumex though, but another problem was
ending up with over a dozen cases with multiple versions of the same package
installed, in the end I had to remove these manually.

If you have a test case or a way in which I can capture what is happening I'll
be happy to try it out, if this isn't applicable to this bug I'll raise it
elsewhere.

Hi Brian,

Your issue is separate.  This bug is because dbus crashes during upgrade causing
the session to be brought down.

One way this issue could be tested is to do a fresh, original FC6 install and
then grabbing all the updates with -updates-testing enabled.

I did a fresh FC6 install today and performed an update with -updates-testing
enabled.  Everything checks out!  The X session didn't crash and upon restarting
the message bus, the config file was updated.

I'll be pushing to -updates shortly.

Ping. Can we close this?

Yes, I think this is fixed for quite some time.