Bug 589027 - Unexpected packages are installed during update applied to a group
Summary: Unexpected packages are installed during update applied to a group
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Satellite 5
Classification: Red Hat
Component: Server
Version: 530
Hardware: All
OS: Linux
high
high
Target Milestone: ---
Assignee: Milan Zázrivec
QA Contact: Red Hat Satellite QA List
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2010-05-05 07:32 UTC by Peter Bieringer
Modified: 2018-10-27 15:18 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2010-07-14 06:16:44 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Peter Bieringer 2010-05-05 07:32:37 UTC
Description of problem:
Unexpected packages are installed during update applied to a group, but this was not mentioned in the list to "confirm"

Version-Release number of selected component (if applicable):
spacewalk-*-0.5.28-49


How reproducible:
Mostly

Steps to Reproduce:
Because of one-way, hard to reproduce in production environment, but here the description:

some days ago, new packages tzdata-java-2010i-1.el5 and tzdata-2010i-1.el5 were released. This updates were applied to a group of systems, where some of them have tzdata-java already installed, some not.

I'm very sure, that the confirmation page has shown up the tzdata-java package only on the related systems (where it was already installed before).

Nevertheless, after all systems did their job (triggered via "osad"), suddenly on systems, where tzdata-java was NOT installed before, it's now also installed.

# zgrep tzdata /var/log/rpmpkgs*
/var/log/rpmpkgs:tzdata-2010i-1.el5.i386.rpm
/var/log/rpmpkgs:tzdata-java-2010i-1.el5.i386.rpm  <----!!!
/var/log/rpmpkgs.10.gz:tzdata-2009u-1.el5.noarch.rpm
/var/log/rpmpkgs.11.gz:tzdata-2009u-1.el5.noarch.rpm
/var/log/rpmpkgs.12.gz:tzdata-2009u-1.el5.noarch.rpm
/var/log/rpmpkgs.1.gz:tzdata-2010f-10.el5.i386.rpm
/var/log/rpmpkgs.2:tzdata-2008i-1.el5.noarch.rpm
/var/log/rpmpkgs.2.gz:tzdata-2010f-10.el5.i386.rpm
/var/log/rpmpkgs.3:tzdata-2008i-1.el5.noarch.rpm
/var/log/rpmpkgs.3.gz:tzdata-2010f-10.el5.i386.rpm
/var/log/rpmpkgs.4:tzdata-2008i-1.el5.noarch.rpm
/var/log/rpmpkgs.4.gz:tzdata-2010f-10.el5.i386.rpm
/var/log/rpmpkgs.5.gz:tzdata-2010f-10.el5.i386.rpm
/var/log/rpmpkgs.6.gz:tzdata-2010e-1.el5.noarch.rpm
/var/log/rpmpkgs.7.gz:tzdata-2010e-1.el5.noarch.rpm
/var/log/rpmpkgs.8.gz:tzdata-2010c-1.el5.noarch.rpm
/var/log/rpmpkgs.9.gz:tzdata-2009u-1.el5.noarch.rpm

# zgrep tzdata /var/log/yum.log*
/var/log/yum.log.1.gz:Apr 21 16:18:01 Updated: tzdata.noarch 2009f-1.el5
/var/log/yum.log.1.gz:Jun 20 16:46:30 Updated: tzdata.noarch 2009i-2.el5
/var/log/yum.log.1.gz:Aug 18 07:59:44 Updated: tzdata-2009k-1.el5.noarch
/var/log/yum.log.2.gz:Sep 16 11:48:15 Updated: tzdata - 2008e-1.el5.noarch
/var/log/yum.log.2.gz:Oct 15 10:19:51 Updated: tzdata.noarch 2008f-3.el5
/var/log/yum.log.2.gz:Nov 07 10:19:52 Updated: tzdata.noarch 2008i-1.el5

# zgrep tzdata /var/log/up2date*
/var/log/up2date:[Tue May  4 07:32:13 2010] up2date Adding packages to package profile: ['tzdata-java-2010i-1.el5', 'tzdata-2010i-1.el5']
/var/log/up2date.1.gz:[Thu Apr  1 11:21:51 2010] up2date Adding packages to package profile: ['tzdata-2010f-10.el5']
/var/log/up2date.2.gz:[Thu Mar 11 12:44:11 2010] up2date Adding packages to package profile: ['tzdata-2010c-1.el5']
/var/log/up2date.2.gz:[Fri Mar 19 09:42:33 2010] up2date Adding packages to package profile: ['kernel-2.6.18-164.15.1.el5', 'cpio-2.6-23.el5_4.1', 'cyrus-sasl-2.1.22-5.el5_4.3', 'cyrus-sasl-lib-2.1.22-5.el5_4.3', 'cyrus-sasl-plain-2.1.22-5.el5_4.3', 'pam-0.99.6.2-]


Entry in the Event History:

Package Install scheduled by ****
Details: 	This action will be executed after 05/ 4/10 7:31:26 AM UTC.

This action's status is: Completed.
The client picked up this action on 05/ 4/10 7:31:34 AM UTC.
The client completed this action on 05/ 4/10 7:32:15 AM UTC.
Client execution returned "Update Succeeded" (code 0)
Packages Scheduled:

    * tzdata-java-2010i-1.el5
    * tzdata-2010i-1.el5


This entry is strange, because it was sure not triggered in this case.

Can it be that the system misbehaves in this case?

Note: such happens on more systems in the past in different scenarios, e.g. suddenly, a httpd was installed by applying updates to a group of sysytems where some have package already installed and some not.

Either the server triggers a wrong command or the client executes it in a wrong manner.

Comment 1 Peter Bieringer 2010-05-05 07:42:56 UTC
The problem is reproducable, here the scenario:

System A: tzdata installed
System B: tzdata & tzdata-java installed

RHN Satellite: spacewalk-*-0.5.28-54


System A:
# yum remove tzdata-java (remove leftover)
# yum downgrade tzdata


System B:

# yum downgrade tzdata-java tzdata


Satellite: Systems -> System Group -> Select Group containing both systems -> work with group -> Packages -> Upgrade existing packages -> Select tzdata (Amount of systems = 2) and tzdata-java (Amount of systems = 1) -> Upgrade selected packages -> Approve list:


System A	tzdata-2010i-1.el5-i386
System B 	tzdata-2010i-1.el5-i386 tzdata-java-2010i-1.el5-i386

-> Confirm

Check up2date logs:

System A:

[Wed May  5 07:34:32 2010] up2date Updating package profile
[Wed May  5 07:35:01 2010] up2date Adding packages to package profile: ['tzdata-2010f-10.el5']
[Wed May  5 07:35:01 2010] up2date Removing packages from package profile: ['tzdata-2010i-1.el5']
[Wed May  5 07:35:01 2010] up2date Updating package profile
[Wed May  5 07:37:13 2010] up2date updateLoginInfo() login info
[Wed May  5 07:37:13 2010] up2date logging into up2date server
[Wed May  5 07:37:13 2010] up2date successfully retrieved authentication token from up2date server
[Wed May  5 07:37:20 2010] up2date Adding packages to package profile: ['tzdata-java-2010i-1.el5', 'tzdata-2010i-1.el5']    <---!!!!!! WHY tzdata-java ALSO ????
[Wed May  5 07:37:20 2010] up2date Removing packages from package profile: []
[Wed May  5 07:37:20 2010] up2date Updating package profile
[Wed May  5 07:37:21 2010] up2date Updating package profile

System B:

[Wed May  5 07:35:33 2010] up2date successfully retrieved authentication token from up2date server
[Wed May  5 07:36:02 2010] up2date Adding packages to package profile: ['tzdata-2010f-10.el5', 'tzdata-java-2010f-10.el5']
[Wed May  5 07:36:02 2010] up2date Removing packages from package profile: ['tzdata-2010i-1.el5', 'tzdata-java-2010i-1.el5']
[Wed May  5 07:36:02 2010] up2date Updating package profile
[Wed May  5 07:37:13 2010] up2date updateLoginInfo() login info
[Wed May  5 07:37:13 2010] up2date logging into up2date server
[Wed May  5 07:37:13 2010] up2date successfully retrieved authentication token from up2date server
[Wed May  5 07:37:19 2010] up2date Adding packages to package profile: ['tzdata-2010i-1.el5', 'tzdata-java-2010i-1.el5']
[Wed May  5 07:37:19 2010] up2date Removing packages from package profile: []
[Wed May  5 07:37:19 2010] up2date Updating package profile
[Wed May  5 07:37:20 2010] up2date Updating package profile

Comment 2 Peter Bieringer 2010-05-05 07:49:58 UTC
Here's the debug log of up2date from System A, looks like the XML action file is not created properly for this system or the update mechanism of the client is without condition, whether the package is already installed or not.

[Wed May  5 07:47:40 2010] up2date D: check_action {'action': "<?xml version='1.0'?>\n<methodCall>\n<methodName>packages.update</methodName>\n<params>\n<param>\n<value><array><data>\n<value><array><data>\n<value><string>tzdat}
[Wed May  5 07:47:40 2010] up2date updateLoginInfo() login info
[Wed May  5 07:47:40 2010] up2date D: login(forceUpdate=True) invoked
[Wed May  5 07:47:40 2010] up2date logging into up2date server
[Wed May  5 07:47:40 2010] up2date D: writeCachedLogin() invoked
[Wed May  5 07:47:40 2010] up2date D: Wrote pickled loginInfo at  1273045660.99  with expiration of  1273049260.99  seconds.
[Wed May  5 07:47:40 2010] up2date successfully retrieved authentication token from up2date server
[Wed May  5 07:47:40 2010] up2date D: logininfo: {'X-RHN-Server-Id': 1000010023, 'X-RHN-Auth-Server-Time': '1273045660.99', 'X-RHN-Auth': '***', 'X-RHN-Auth-Channels': [['rhel-i386-server-5', '20100504131}
[Wed May  5 07:47:40 2010] up2date D: handle_action {'action': "<?xml version='1.0'?>\n<methodCall>\n<methodName>packages.update</methodName>\n<params>\n<param>\n<value><array><data>\n<value><array><data>\n<value><string>tzda}
[Wed May  5 07:47:40 2010] up2date D: handle_action actionid = 15441, version = 2
[Wed May  5 07:47:40 2010] up2date D: do_call packages.update ([['tzdata', '2010i', '1.el5', '', 'i386'], ['tzdata-java', '2010i', '1.el5', '', 'i386']],)
[Wed May  5 07:47:41 2010] up2date D: Called update [['tzdata', '2010i', '1.el5', '', 'i386'], ['tzdata-java', '2010i', '1.el5', '', 'i386']]
[Wed May  5 07:47:43 2010] up2date D: Dependencies Resolved
[Wed May  5 07:47:43 2010] up2date D: Downloading Packages:
[Wed May  5 07:47:44 2010] up2date D: Running Transaction Test
[Wed May  5 07:47:44 2010] up2date D: Finished Transaction Test
[Wed May  5 07:47:44 2010] up2date D: Transaction Test Succeeded
[Wed May  5 07:47:44 2010] up2date D: Running Transaction
[Wed May  5 07:47:45 2010] up2date Adding packages to package profile: ['tzdata-java-2010i-1.el5', 'tzdata-2010i-1.el5']
[Wed May  5 07:47:45 2010] up2date Removing packages from package profile: []
[Wed May  5 07:47:45 2010] up2date Updating package profile
[Wed May  5 07:47:46 2010] up2date D: Sending back response (0, 'Update Succeeded', {})
[Wed May  5 07:47:47 2010] up2date D: do_call packages.checkNeedUpdate ('rhnsd=1',)
[Wed May  5 07:47:47 2010] up2date D: Called refresh_rpmlist
[Wed May  5 07:47:47 2010] up2date Updating package profile
[Wed May  5 07:47:47 2010] up2date D: local action status:  (0, 'rpmlist refreshed', {})

Comment 3 Peter Bieringer 2010-05-05 08:04:48 UTC
Just as a side note, this issue is independend of used client side software, it rises at least up using the RHEL 5.5 default RHN client tools and the ones from Spacewalk 0.8.

Comment 4 Clifford Perry 2010-05-12 14:05:41 UTC
Hi Peter Bieringer      
Could you please open a support ticket to associate and track next to this bug report. This will allow for Red Hat support to triage, confirm replication and help Engineering - sometimes providing a fix before we even start looking at the bug report. 

Regards,
Cliff.

Comment 5 Peter Bieringer 2010-05-12 14:28:34 UTC
Case was already opened after writing bz entry: Case# 2018786

Comment 8 Milan Zázrivec 2010-06-29 13:17:20 UTC
I cannot reproduce the problem according to the scenario provided in
comment #0 and comment #1.

With latest Satellite 5.3.0, two RHEL 5.5 clients registered, the scenario
with tzdata & tzdata-java works as expected.

The only way I can achieve the results customer is reporting is when I do:
1. I have both tzdata, tzdata-java installed
2. downgrade tzdata
3. rpm -e tzdata-java
 - it is important to use rpm -e rather than yum remove: removing the
   package using rpm -e (unlike yum remove) won't update package profile
   on the server.
4. Schedule update on the server (although here server would see that
both tzdata & tzdata-java need to be updated)
5. After the update is over, I can see updated tzdata-java is back

It might be that the client systems in question do not have the package
profile synced properly (rhn-profile-sync helps in these situations).

Nonetheless, I'm unable to reproduce the problem. If anyone else is able
to reproduce it (as comment #6 suggests), I'll certainly appreciate 
the input on it. Thanks

Comment 9 Peter Bieringer 2010-07-02 13:00:39 UTC
Just note that I can't reproduce this anymore, too, testing with kernel/kernel-headers/kernel-devel and tzdata/tzdata-java

Can it be that this issue was silently fixed in the 0.5.28-55 release, installed May 27 on my system?

Comment 11 Milan Zázrivec 2010-07-02 13:43:57 UTC
(In reply to comment #9)
> Just note that I can't reproduce this anymore, too, testing with
> kernel/kernel-headers/kernel-devel and tzdata/tzdata-java
> 
> Can it be that this issue was silently fixed in the 0.5.28-55 release,
> installed May 27 on my system?    

I've checked the changes in the code between those two versions and
I found nothing obvious that could be causing the reported problem
to go away.

Nonetheless, the backend version I've been using for reproducing the
problem is 0.5.28-55 as well.

Comment 13 Milan Zázrivec 2010-07-14 06:16:44 UTC
Closing based on previous comments.


Note You need to log in before you can comment on or make changes to this bug.