Problems with package reporting

[Andreas Hasenack]

I have been experiencing problems with package reporting lately. Basically the server says there are updates available for a certain computer, but when you click on the number of updates in the packages page, nothing is listed. Likewise, if you click on security updates, nothing is listed, even though the packages page even has an USN for the computer.

I also saw problems with "request all upgrades". An activity would come back with things like "Remove package unknown", signaling some serious problem with the hash-id mapping of packages.

What I have debugged so far is this:
- the update_stamp_filename (/var/lib/landscape/client/package/update-stamp) is only created by the reporter's run_apt_update()
- if that file does not exist, the package changer refuses to run (and I have seen this in the logs). That by itself means the changer could be locked up for up to 6h (the default apt_update_interval value):

        if not self.update_stamp_exists():
            logging.warning("The package-reporter hasn't run yet, exiting.")
            return succeed(None)

 ==> /var/log/landscape/package-changer.log <==
2013-02-27 13:48:59,008 WARNING [MainThread] The package-reporter hasn't run yet, exiting.

Still, this shouldn't block the reporter from requesting and reporting hashes, right, and indeed doesn't seem to (extra logging changes applied locally):
2013-02-27 15:07:35,077 INFO [MainThread] Queuing request for package hash => id translation on 108 hash(es).
2013-02-27 15:08:35,835 INFO [MainThread] apt_update_interval=21600
2013-02-27 15:08:35,835 INFO [MainThread] force_apt_update=False
2013-02-27 15:08:35,837 INFO [MainThread] _apt_sources_have_changed() = False
2013-02-27 15:08:35,837 INFO [MainThread] _apt_update_timeout_expired(21600)=False
2013-02-27 15:08:35,837 INFO [MainThread] os.path.exists(/var/lib/landscape/client/package/update-stamp) = False
2013-02-27 15:08:35,837 INFO [MainThread] '/usr/lib/landscape/apt-update' didn't run, update interval has not passed
2013-02-27 15:08:35,847 INFO [MainThread] Received 108 package hash => id translations, 0 hashes are unknown.

Still, this machine in particular is reporting 3 upgrades available, but when you click on the number nothing is listed. It will only get "in sync" if run_apt_update() runs. Basically, I can call landscape-package-reporter with --force-apt-update:

# sudo -u landscape landscape-package-reporter --force-apt-update
2013-02-27 15:37:30,500 INFO [MainThread] apt_update_interval=21600
2013-02-27 15:37:30,501 INFO [MainThread] force_apt_update=True
2013-02-27 15:37:30,502 INFO [MainThread] _apt_sources_have_changed() = False
2013-02-27 15:37:30,502 INFO [MainThread] _apt_update_timeout_expired(21600)=False
2013-02-27 15:37:30,503 INFO [MainThread] os.path.exists(/var/lib/landscape/client/package/update-stamp) = False
2013-02-27 15:37:49,611 INFO [MainThread] Queuing request for package hash => id translation on 4 hash(es).
2013-02-27 15:37:52,218 INFO [MainThread] Queuing message with changes in known packages: 17 installed, 596 available, 8 available upgrades, 0 locked, 0 not installed, 0 not available, 0 not available upgrades, 0 not locked.

So maybe what it before this forced run was just the state of the hash-id-database file, not even considering what the system's previous apt-get update run brought in (taken from the timestamp of /var/lib/apt/periodic/update-success-stamp).

[Andreas Hasenack (ahasenack)]

Here is some logging with a full session. I started with a clean /var/lib/landscape/client and registered the client.

At the end of this, the UI was showing, for this computer:
Available: 43311
Installed: 429
Upgrades: 3 (link)
Held: -

If you click on the 3 upgrades link, it takes you to an empty listing.

Here are the logs, in chronological order:

tail -F /var/log/landscape/{broker,package-changer,package-reporter}.log
==> /var/log/landscape/broker.log <==
2013-02-27 16:17:32,498 INFO [PoolThread-twisted.internet.reactor-1] Sent 636 bytes and received 178 bytes in 0.09s.
2013-02-27 16:17:32,498 INFO [MainThread] Switching to normal exchange mode.
2013-02-27 16:17:32,499 INFO [MainThread] Server UUID changed (old=None, new=f166d22c-7c25-11e2-bbc0-525400ba0fdc).
2013-02-27 16:17:32,500 INFO [MainThread] Accepted types changed: +test +register +register-provisioned-machine +register-cloud-vm
2013-02-27 16:17:32,517 INFO [MainThread] Queueing message to register with account 'standalone' and tags grizzly,cloud with a password.
2013-02-27 16:17:32,518 INFO [MainThread] Starting message exchange with https://inst-025.virtual-maas.com/message-system.
2013-02-27 16:17:32,522 INFO [MainThread] Message exchange completed in 0.12s.
2013-02-27 16:17:32,795 INFO [PoolThread-twisted.internet.reactor-1] Sent 873 bytes and received 180 bytes in 0.27s.
2013-02-27 16:17:32,797 INFO [MainThread] Using new secure-id ending with SWbi0UGoFO for account standalone.
2013-02-27 16:17:32,799 INFO [MainThread] Message exchange completed in 0.28s.
tail: cannot open `/var/log/landscape/package-changer.log' for reading: No such file or directory
tail: cannot open `/var/log/landscape/package-reporter.log' for reading: No such file or directory

==> /var/log/landscape/broker.log <==
2013-02-27 16:18:02,801 INFO [MainThread] Ping indicates message available. Scheduling an urgent exchange.
2013-02-27 16:18:32,799 INFO [MainThread] Starting urgent message exchange with https://inst-025.virtual-maas.com/message-system.
2013-02-27 16:18:32,801 INFO [MainThread] Ping indicates message available. Scheduling an urgent exchange.
2013-02-27 16:18:32,939 INFO [PoolThread-twisted.internet.reactor-2] Sent 636 bytes and received 801 bytes in 0.14s.
2013-02-27 16:18:32,940 INFO [MainThread] Switching to normal exchange mode.
2013-02-27 16:18:32,941 INFO [MainThread] Accepted types changed: +computer-info +operation-result +ceph-usage +memory-info +mount-info +text-message +network-activity +mount-activity +custom-graph +active-process-info +update-manager-info +reboot-required +change-packages-result +temperature +apt-preferences +keystone-token +users +reboot-required-info +cpu-usage +package-reporter-result +hardware-info +load-average +packages +unknown-package-hashes +add-packages +free-space +action-info +resynchronize +processor-info +swift-device-info +network-device +distribution-info test -register -register-provisioned-machine -register-cloud-vm
2013-02-27 16:18:32,954 INFO [MainThread] Message exchange completed in 0.15s.
tail: `/var/log/landscape/package-reporter.log' has become accessible

==> /var/log/la...

[Andreas Hasenack (ahasenack)]

Out of curiosity, I changed /etc/apt/sources.list and restarted the client. apt ran, and it updated the packages on the server for this computer:

# echo >> /etc/apt/sources.list
# /etc/init.d/landscape-client restart
 * Stopping landscape-client daemon !tail
                                                                                                                                                 [ OK ]
 * Starting the landscape-client daemon [ OK ]
root@inst-022:/var/lib/landscape/client# !tail
tail -F /var/log/landscape/{broker,package-changer,package-reporter}.log
(...)
==> /var/log/landscape/broker.log <==
2013-02-27 16:37:33,549 INFO [MainThread] Broker started with config /etc/landscape/client.conf

==> /var/log/landscape/package-changer.log <==
2013-02-27 16:37:40,079 WARNING [MainThread] The package-reporter hasn't run yet, exiting.

==> /var/log/landscape/package-reporter.log <==
2013-02-27 16:37:40,955 INFO [MainThread] apt_update_interval=21600
2013-02-27 16:37:40,956 INFO [MainThread] force_apt_update=False
2013-02-27 16:37:40,957 INFO [MainThread] _apt_sources_have_changed() = True
2013-02-27 16:37:40,957 INFO [MainThread] _apt_update_timeout_expired(21600)=False
2013-02-27 16:37:40,958 INFO [MainThread] os.path.exists(/var/lib/landscape/client/package/update-stamp) = False
2013-02-27 16:38:01,538 INFO [MainThread] Queuing message with changes in known packages: 17 installed, 600 available, 10 available upgrades, 0 locked, 0 not installed, 0 not available, 0 not available upgrades, 0 not locked.

==> /var/log/landscape/package-changer.log <==
2013-02-27 16:38:11,221 INFO [MainThread] Queuing response with change package results to exchange urgently.

==> /var/log/landscape/package-reporter.log <==
2013-02-27 16:38:11,951 INFO [MainThread] apt_update_interval=21600
2013-02-27 16:38:11,952 INFO [MainThread] force_apt_update=False
2013-02-27 16:38:11,953 INFO [MainThread] _apt_sources_have_changed() = True
2013-02-27 16:38:11,953 INFO [MainThread] _apt_update_timeout_expired(21600)=False
2013-02-27 16:38:11,954 INFO [MainThread] os.path.exists(/var/lib/landscape/client/package/update-stamp) = True
2013-02-27 16:38:31,626 INFO [MainThread] Queuing message with changes in known packages: 0 installed, 0 available, 0 available upgrades, 0 locked, 1 not installed, 0 not available, 0 not available upgrades, 0 not locked.

==> /var/log/landscape/broker.log <==
2013-02-27 16:38:33,558 INFO [MainThread] Starting urgent message exchange with https://inst-025.virtual-maas.com/message-system.
2013-02-27 16:38:34,644 INFO [PoolThread-twisted.internet.reactor-1] Sent 26799 bytes and received 150 bytes in 1.08s.
2013-02-27 16:38:34,644 INFO [MainThread] Switching to normal exchange mode.
2013-02-27 16:38:34,646 INFO [MainThread] Message exchange completed in 1.09s.

Now the UI is showing me, for this computer:
Available: 43911
Installed: 445
Upgrades: 1...

[Andreas Hasenack (ahasenack)]

Oops, forgot to add an important detail to the run from comment #1. Before registering that client, I ran apt-get update, so the package information on the machine was as up-to-date as possible.

[Thomas Herve (therve)]

I've fixed the changer check of the notifier stamp file in r632. Everything else sounds weird to me, let's talk about it.