Event posted on 2009-10-05 08:35 BST by cbuissar

Hi Seg,

A customer is complaining that RHEL5 does not log which packages are being updated/removed when done from RHN.
Since a system administrator should be noticed from any package update being done remotely, this could be considered as an important issue.

Actually this behavior appeared since RHEL5.3


1. Time and date of problem:

Always since RHEL 5.3

2. System architecture(s):
noarch

3. Provide a clear and concise problem description as it is understood at the time of escalation.. 
   Observed behavior:
And since RHEL5.3, we can see, when updating a machine from RHN/Satellite :
----8<----
[Sun Oct  4 17:26:48 2009] up2date Updating package profile
---->8----

   Desired behavior: 
The same as RHEL5.2 :
----8<----
[Sun Oct  4 17:42:02 2009] up2date Adding packages to package profile: ['wget-1.11.4-2.el5']
[Sun Oct  4 17:42:02 2009] up2date Removing packages from package profile: []
---->8----

4. Specific action requested of SEG:
Find the best possible way to fix lack of logging

5. Is a defect (bug) in the product suspected? 
yes

6. Does a proposed patch exist? 
no

7. What is the impact to the customer when they experience this problem?
The machine admin should be able to get notified of what is being installed/updated.
This customer is using some scripts to check the logs.


=======================

1. Other actions already taken in working the problem

See next post


2. Attach sosreport.

Attached : sosreport of a rhel5.3 machine, with updated rhn/yum packages.

4. Provide issue reproduction information, including location and access of reproducer machine, if available.

   Steps to reproduce the problem:
-> From a Satellite, prepare some upgrade event
-> run rhn_check to trigger the event from the client

Let me know if you need further info,

Cédric
This event sent from IssueTracker by mpoole  [Support Engineering Group]
 issue 350407

Event posted on 2009-10-05 08:37 BST by cbuissar

/var/log/updates example from RHEL5.2  :
----8<----
[Sun Oct  4 17:42:02 2009] up2date Adding packages to package profile:
['wget-1.11.4-2.el5']
[Sun Oct  4 17:42:02 2009] up2date Removing packages from package profile:
[]
---->8----

And since RHEL5.3, it became :
----8<----
[Sun Oct  4 17:26:48 2009] up2date Updating package profile
---->8----


The issue is coming from the fact that in RHEL5.2, the function
posttrans_hook from /usr/lib/yum-plugins/rhnplugin.py  was calling
rhnPackageInfo.remoteDeltaPackages(delta) which is called with a package
list, which was logged :

/usr/lib/yum-plugins/rhnplugin.py, RHEL 5.2  :
----8<----
def posttrans_hook(conduit):
    """ Post rpm transaction hook. We update the RHN profile here.
"""
    global rhn_enabled
    if rhn_enabled:
        ts_info = conduit.getTsInfo()
        delta = make_package_delta(ts_info)
        try:
            rhnPackageInfo.remoteDeltaPackages(delta)               #
<==== HERE
        except up2dateErrors.RhnServerException, e:
            conduit.error(0, COMMUNICATION_ERROR + "\n" +
                _("Package profile information could not be sent.") +
"\n" +
                str(e))
---->8----

RHEL 5.3 :
----8<----
def posttrans_hook(conduit):
    """ Post rpm transaction hook. We update the RHN profile here.
"""
    global rhn_enabled
    if rhn_enabled:
        try:
            rhnPackageInfo.updatePackageProfile()                  # <====
HERE
        except up2dateErrors.RhnServerException, e:
            conduit.error(0, COMMUNICATION_ERROR + "\n" +
                _("Package profile information could not be sent.") +
"\n" +
                str(e))
---->8----


From /usr/lib/yum-plugins/rhnplugin.py :
----8<----
def remoteDeltaPackages(pkgs):
    log = up2dateLog.initLog()
    log.log_me("Adding packages to package profile: %s" %
               pprint_pkglist(pkgs['added']))
    log.log_me("Removing packages from package profile: %s" %
               pprint_pkglist(pkgs['removed']))
    s = rhnserver.RhnServer()

    s.registration.delta_packages(up2dateAuth.getSystemId(), pkgs)
---->8----

In newer packages, the function called is
rhnPackageInfo.updatePackageProfile().

----8<----
def updatePackageProfile():
    log = up2dateLog.initLog()
    log.log_me("Updating package profile")
    s = rhnserver.RhnServer()
    s.registration.update_packages(up2dateAuth.getSystemId(),
        rpmUtils.getInstalledPackageList(getArch=1))
---->8----


=> A Solution could be :
To bypass, this change, an easy solution could be to make some changes in
/usr/share/rhn/actions/packages.py
Changing the    log.log_debug("Called update", package_list) calls to
log_me calls in the functions :
def remove(package_list):
def update(package_list):


Issue escalated to Support Engineering Group by: cbuissar.
cbuissar assigned to issue for EMEA Production Escalation.
Category set to: Applications::Bug Fix
Internal Status set to 'Waiting on SEG'
Status set to: Waiting on Tech

This event sent from IssueTracker by mpoole  [Support Engineering Group]
 issue 350407

Sure - I'm not sure how it fits in priority wise yet - I'm including Cliff so he's aware of it.

Also this bug may be related to 522805

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

That suggested (from #2) approach to do changes /usr/share/rhn/actions/packages.py
in remove() and update() do not work.
It work for update, but do not work (dunno why) for remove. And it works only for actions initiated by satellite (i.e executed by rhn_check or osad). It do not work if you manually run "yum install foo". That worked in 5.2 too.

So I took different approach. I partially reverted that changes (commit 20566c5ea64527c9159104b7c61bb70b149b6318). We will still do count that delta, but we will not use it to send to rhnParent [1], but only to write these messages to log. And since most users probably do not cares about those messages in log and will mean for them only slow down, I introduced new variable in /etc/sysconfig/rhn/up2date. It is named writeChangesToLog and when set to 1 it will restore old behaviour. When left on 0 (the default) it will behave as in 5.3 and 5.4, i.e. will not write to log the deltas.

[1]: because we do not want to reintroduce bug, why was fixed in 20566c5ea64527c9159104b7c61bb70b149b6318

Commited to Spacewalk git as
0fec81b0d9c530eaf283522104c7995fb5719cc6
6898b5ea1dd655d581fd2a1712a98ea45395e93a

To svn as revision 188954

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

To avoid strange logwatch output, could you please skip the log, if array is empty? Each install also triggers:

[Thu Dec 17 14:40:29 2009] up2date Removing packages from package profile: []

Which result later in logwatch output, e.g.:

 Package Added To Profile:
    ['aalib-devel-1.4.0-0.11.rc5.el5', 'aalib-1.4.0-0.11.rc5.el5', 'libX11-1.0.3-11.el5', 'libXau-1.0.1-3.1', 'libXdmcp-1.0.1-2.1', 'xorg-x11ilesystem-7.1-2.fc6']

 Package Removed From Profile:
    []

Thank you!

# VERIFIED

Package(s) fixing the issue:
yum-rhn-plugin-0.5.4-15.el5.noarch.rpm

Checked: RHEL 5.5 [Client,Server] v20100117.0

Scenario: Checked logging of packages while getting installed/removed (update of the package in this context also considering as installation).
The "writeChangesToLog=1" should be present in /etc/sysconfig/rhn/up2date
Work of yum (client-side); osad, rhnsd and rhn_check are verified in install/localinstall/remove/update of packages...

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2010-0269.html