E-mail report contains repeated "Reading database ... NN%" lines

Bug #1599646 reported by Daniel Richard G. on 2016-07-06
30
This bug affects 6 people
Affects Status Importance Assigned to Milestone
apt (Debian)
New
Unknown
unattended-upgrades (Ubuntu)
Undecided
Unassigned
Xenial
Undecided
Unassigned
Bionic
Wishlist
Unassigned
Cosmic
Undecided
Unassigned

Bug Description

[Impact]

 * Unattended-upgrades sends the following repeating dpkg progress lines with almost no informational value in the email report:
...
 (Reading database ...
 (Reading database ... 5%
 (Reading database ... 10%
 (Reading database ... 15%
 (Reading database ... 20%
 (Reading database ... 25%
 (Reading database ... 30%
 (Reading database ... 35%
 (Reading database ... 40%
 (Reading database ... 45%
 (Reading database ... 50%
 (Reading database ... 55%
 (Reading database ... 60%
 (Reading database ... 65%
 (Reading database ... 70%
 (Reading database ... 75%
 (Reading database ... 80%
 (Reading database ... 85%
 (Reading database ... 90%
 (Reading database ... 95%
(Reading database ... 60486 files and directories currently installed.)
...

 * This makes the report email too verbose and makes harder to spot real problems.

[Test Case]

 * Run package autopkgtest and observe no such lines in the echoed email in upgrade-all-security and upgrade-between-snapshots tests.

[Regression Potential]

 * The fix filters dpkg's output only and in the worst case other lines could be missing or u-u could crash. Since the applied hard-coded regex pattern is fairly simple and we observed no crashes in the tests those regressions are unlikey to occur.

[Originial Bug Text]

This concerns unattended-upgrades 0.90 in Xenial.

Here is an excerpt from an e-mail report sent out by u-u after the upgrade process is completed:

 Package installation log:
 Log started: 2016-07-06 17:24:21
 Preconfiguring packages ...
 (Reading database ...
 (Reading database ... 5%
 (Reading database ... 10%
 (Reading database ... 15%
 (Reading database ... 20%
 (Reading database ... 25%
 (Reading database ... 30%
 (Reading database ... 35%
 (Reading database ... 40%
 (Reading database ... 45%
 (Reading database ... 50%
 (Reading database ... 55%
 (Reading database ... 60%
 (Reading database ... 65%
 (Reading database ... 70%
 (Reading database ... 75%
 (Reading database ... 80%
 (Reading database ... 85%
 (Reading database ... 90%
 (Reading database ... 95%
 (Reading database ... 100%
 (Reading database ... 314949 files and directories currently installed.)
 Preparing to unpack .../tzdata_2016f-0ubuntu0.16.04_all.deb ...
 Unpacking tzdata (2016f-0ubuntu0.16.04) over (2016d-0ubuntu0.16.04) ...
 Preparing to unpack .../libgimp2.0_2.8.16-1ubuntu1.1_i386.deb ...

All but the last "Reading database ..." line should be elided from the message.

As a matter of fact, those lines do not appear in messages mailed out from current Trusty systems (u-u version 0.82.1ubuntu2.4), so this appears to be a regression.

Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in unattended-upgrades (Ubuntu):
status: New → Confirmed
Changed in apt (Debian):
status: Unknown → New
Balint Reczey (rbalint) wrote :
Changed in unattended-upgrades (Ubuntu):
status: Confirmed → Fix Committed
Balint Reczey (rbalint) wrote :

Fixed in u-u 1.6.

Changed in unattended-upgrades (Ubuntu):
status: Fix Committed → Fix Released
Daniel Richard G. (skunk) wrote :

Could this be SRU'ed into Bionic?

18.04LTS currently has version 1.1, so the "Reading database ..." lines will otherwise afflict it for quite some time to come.

Balint Reczey (rbalint) wrote :

@skunk I nominated the fix as it is very isolated and would make u-u usage more pleasant, but a second opinion from release management is welcome.

Changed in unattended-upgrades (Ubuntu Bionic):
status: New → Confirmed
Brian Murray (brian-murray) wrote :

I don't know if Balint considers me release management but fixing this in an SRU is fine with me.

Balint Reczey (rbalint) wrote :

@brian-murray Absolutely, and thanks for the green light.
I have committed it to be part of the next SRU:
https://github.com/mvo5/unattended-upgrades/tree/ubuntu/bionic

Changed in unattended-upgrades (Ubuntu Bionic):
status: Confirmed → Fix Committed
importance: Undecided → Wishlist
Balint Reczey (rbalint) on 2019-01-31
description: updated

Hello Daniel, or anyone else affected,

Accepted unattended-upgrades into cosmic-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/unattended-upgrades/1.5ubuntu3.18.10.2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-cosmic to verification-done-cosmic. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-cosmic. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Changed in unattended-upgrades (Ubuntu Cosmic):
status: New → Fix Committed
tags: added: verification-needed verification-needed-cosmic
Balint Reczey (rbalint) wrote :

Verified on unattended-upgrades/1.5ubuntu3.18.10.2 for Cosmic:

https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-cosmic/cosmic/amd64/u/unattended-upgrades/20190221_173137_1ecf7@/log.gz :
...
From root@autopkgtest Thu Feb 21 17:09:54 2019
Return-path: <root@autopkgtest>
Envelope-to: root@autopkgtest
Delivery-date: Thu, 21 Feb 2019 17:09:54 +0000
Received: from root by autopkgtest with local (Exim 4.91)
 (envelope-from <root@autopkgtest>)
 id 1gwrr8-0001k8-Ag
 for root@autopkgtest; Thu, 21 Feb 2019 17:09:54 +0000
Subject: [package on hold] unattended-upgrades result for adt-cosmic-amd64-unattended-upgrades-20190221-165334.novalocal: SUCCESS
To: root@autopkgtest
Auto-Submitted: auto-generated
MIME-Version: 1.0
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: quoted-printable
From: root <root@autopkgtest>
Message-Id: <E1gwrr8-0001k8-Ag@autopkgtest>
Date: Thu, 21 Feb 2019 17:09:54 +0000

Unattended upgrade result: All upgrades installed

Packages that were upgraded:
 apt apt-utils dirmngr distro-info-data gnupg gnupg-l10n gnupg-utils
 gpg gpg-agent gpg-wks-client gpg-wks-server gpgconf gpgsm gpgv gvfs
 gvfs-common gvfs-daemons gvfs-libs initramfs-tools
 initramfs-tools-bin initramfs-tools-core krb5-locales libapt-inst2.0
 libapt-pkg5.0 libavahi-client3 libavahi-common-data libavahi-common3
 libavahi-glib1 libcaca0 libcups2 libgssapi-krb5-2
 libjavascriptcoregtk-4.0-18 libk5crypto3 libkrb5-3 libkrb5support0
 libmysqlclient20 libnss-systemd libnss3 libpam-systemd libperl5.26
 libpolkit-agent-1-0 libpolkit-backend-1-0 libpolkit-gobject-1-0
 libpoppler-glib8 libpoppler79 libssl1.0.0 libssl1.1 libsystemd0
 libtiff5 libudev1 libwavpack1 libwebkit2gtk-4.0-37 openssh-client
 openssl perl perl-base perl-modules-5.26 policykit-1
 python3-requests snapd systemd systemd-sysv tzdata udev
 xserver-common xserver-xorg-core xserver-xorg-legacy
Packages with upgradable origin but kept back:
 libpython3.6-minimal libpython3.6-stdlib python3.6 python3.6-minimal

Packages that were auto-removed:
 libncursesw5 libtinfo5

Package installation log:
Log started: 2019-02-21 17:08:07
Preparing to unpack .../distro-info-data_0.38ubuntu0.1_all.deb ...
Unpacking distro-info-data (0.38ubuntu0.1) over (0.38) ...
Setting up distro-info-data (0.38ubuntu0.1) ...
Log ended: 2019-02-21 17:08:09
...

tags: added: verification-done-cosmic
removed: verification-needed-cosmic
Balint Reczey (rbalint) wrote :

Verified with unattended-upgrades/1.1ubuntu1.18.04.9 on Bionic:

https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-bionic/bionic/amd64/u/unattended-upgrades/20190221_190835_4cafb@/log.gz :

...
From: root <root@autopkgtest>
Message-Id: <E1gwsoF-0001Qi-Gv@autopkgtest>
Date: Thu, 21 Feb 2019 18:10:59 +0000

Unattended upgrade returned: True

Packages that were upgraded:
 apparmor apport apt apt-utils base-files dirmngr distro-info-data
 file gnupg gnupg-l10n gnupg-utils gpg gpg-agent gpg-wks-client
 gpg-wks-server gpgconf gpgsm gpgv gvfs gvfs-common gvfs-daemons
 gvfs-libs initramfs-tools initramfs-tools-bin initramfs-tools-core
 krb5-locales libapparmor1 libapt-inst2.0 libapt-pkg5.0
 libavahi-client3 libavahi-common-data libavahi-common3
 libavahi-glib1 libcaca0 libcups2 libdns-export1100 libgcrypt20
 libglib2.0-0 libglib2.0-data libgssapi-krb5-2 libisc-export169
 libjavascriptcoregtk-4.0-18 libjpeg-turbo-progs libjpeg-turbo8
 libk5crypto3 libkrb5-3 libkrb5support0 liblcms2-2 libmagic-mgc
 libmagic1 libmysqlclient20 libnss-systemd libnss3 libpam-systemd
 libpango-1.0-0 libpangocairo-1.0-0 libpangoft2-1.0-0 libperl5.26
 libpng16-16 libpolkit-agent-1-0 libpolkit-backend-1-0
 libpolkit-gobject-1-0 libpoppler-glib8 libpoppler73 libprocps6
 libpython2.7 libpython2.7-minimal libpython2.7-stdlib
 libsoup-gnome2.4-1 libsoup2.4-1 libssl1.1 libsystemd0 libtiff5
 libudev1 libudisks2-0 libwavpack1 libwebkit2gtk-4.0-37 libx11-6
 libx11-data libx11-xcb1 libxkbcommon0 libxml2 netplan.io nplan
 openssl perl perl-base perl-modules-5.26 policykit-1 procps
 python3-apport python3-problem-report python3-requests systemd
 systemd-sysv tzdata udev udisks2 xserver-common xserver-xorg-core
 xserver-xorg-legacy

Package installation log:
Log started: 2019-02-21 18:09:19
Preconfiguring packages ...
Preparing to unpack .../apparmor_2.12-4ubuntu5.1_amd64.deb ...
Unpacking apparmor (2.12-4ubuntu5.1) over (2.12-4ubuntu5) ...
Setting up apparmor (2.12-4ubuntu5.1) ...
Installing new version of config file /etc/apparmor.d/abstractions/private-files ...
Installing new version of config file /etc/apparmor.d/abstractions/private-files-strict ...
Installing new version of config file /etc/apparmor.d/abstractions/ubuntu-browsers.d/user-files ...
Processing triggers for systemd (237-3ubuntu10) ...
Processing triggers for man-db (2.8.3-2) ...
Log ended: 2019-02-21 18:09:20
...

Łukasz Zemczak (sil2100) wrote :

Hello Daniel, or anyone else affected,

Accepted unattended-upgrades into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/unattended-upgrades/1.1ubuntu1.18.04.7~16.04.2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-xenial to verification-done-xenial. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-xenial. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Changed in unattended-upgrades (Ubuntu Xenial):
status: New → Fix Committed
tags: added: verification-needed-xenial
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package unattended-upgrades - 1.5ubuntu3.18.10.2

---------------
unattended-upgrades (1.5ubuntu3.18.10.2) cosmic; urgency=medium

  * Clear cache when autoremoval fails (LP: #1779157)
  * Find autoremovable kernel packages using the patterns in APT's way
    (LP: #1815494)
  * Filter out progress indicator from dpkg log (LP: #1599646)

 -- Balint Reczey <email address hidden> Thu, 21 Feb 2019 15:10:13 +0100

Changed in unattended-upgrades (Ubuntu Cosmic):
status: Fix Committed → Fix Released

The verification of the Stable Release Update for unattended-upgrades has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

Balint Reczey (rbalint) wrote :

Verified with unattended-upgrades/1.1ubuntu1.18.04.7~16.04.2 on Xenial:

https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-xenial/xenial/amd64/u/unattended-upgrades/20190228_150449_11313@/log.gz

...
Packages with upgradable origin but kept back:
 isc-dhcp-client isc-dhcp-common

Packages that were auto-removed:
 libmircommon5

Package installation log:
Log started: 2019-02-28 14:34:48
Preparing to unpack .../distro-info-data_0.28ubuntu0.9_all.deb ...
Unpacking distro-info-data (0.28ubuntu0.9) over (0.28) ...
Setting up distro-info-data (0.28ubuntu0.9) ...
Log ended: 2019-02-28 14:34:48

Log started: 2019-02-28 14:34:49
Preparing to unpack .../procps_2%3a3.3.10-4ubuntu2.4_amd64.deb ...
Running in chroot, ignoring request.
Unpacking procps (2:3.3.10-4ubuntu2.4) over (2:3.3.10-4ubuntu2) ...
Processing triggers for man-db (2.7.5-1) ...
Processing triggers for ureadahead (0.100.0-19) ...
Processing triggers for systemd (229-4ubuntu4) ...
Setting up procps (2:3.3.10-4ubuntu2.4) ...
update-rc.d: warning: start and stop actions are no longer supported; falling back to defaults
Log ended: 2019-02-28 14:34:50
...

tags: added: verification-done verification-done-xenial
removed: verification-needed verification-needed-xenial
Launchpad Janitor (janitor) wrote :
Download full text (33.9 KiB)

This bug was fixed in the package unattended-upgrades - 1.1ubuntu1.18.04.7~16.04.2

---------------
unattended-upgrades (1.1ubuntu1.18.04.7~16.04.2) xenial; urgency=medium

  * Don't check blacklist too early and report updates from not allowed origins
    as kept back. (LP: #1781176)
  * test/test_blacklisted_wrong_origin.py: Fix and enable test
  * Filter out progress indicator from dpkg log (LP: #1599646)
  * Clear cache when autoremoval fails (LP: #1779157)
  * Find autoremovable kernel packages using the patterns in APT's way
    (LP: #1815494)

unattended-upgrades (1.1ubuntu1.18.04.7~16.04.1) xenial; urgency=medium

  * Start service after systemd-logind.service to be able to take inhibition
    lock (LP: #1806487)
  * Handle gracefully when logind is down (LP: #1806487)

unattended-upgrades (1.1ubuntu1.18.04.7~16.04.0) xenial; urgency=medium

  * Backport to Xenial (LP: #1702793)
  * Revert to build-depending on debhelper (>= 9~) and dh-systemd
  * Revert configuration example changes to avoid triggering a debconf question
  * debian/postinst: Update recovery to be triggered on Xenial's package versions

unattended-upgrades (1.1ubuntu1.18.04.7) bionic; urgency=medium

  * Trigger unattended-upgrade-shutdown actions with PrepareForShutdown()
    Performing upgrades in service's ExecStop did not work when the upgrades
    involved restarting services because systemd blocked other stop/start
    actions making maintainer scripts time out and be killed leaving a broken
    system behind.
    Running unattended-upgrades.service before shutdown.target as a oneshot
    service made it run after unmounting filesystems and scheduling services
    properly on shutdown is a complex problem and adding more services to the
    mix make it even more fragile.
    The solution of monitoring PrepareForShutdown() signal from DBus
    allows Unattended Upgrade to run _before_ the jobs related to shutdown are
    queued thus package upgrades can safely restart services without
    risking causing deadlocks or breaking part of the shutdown actions.
    Also ask running unattended-upgrades to stop when shutdown starts even in
    InstallOnShutdown mode and refactor most of unattended-upgrade-shutdown to
    UnattendedUpgradesShutdown class. (LP: #1778219)
  * Increase logind's InhibitDelayMaxSec to 30s. (LP: #1778219)
    This allows more time for unattended-upgrades to shut down gracefully
    or even install a few packages in InstallOnShutdown mode, but is still a
    big step back from the 30 minutes allowed for InstallOnShutdown previously.
    Users enabling InstallOnShutdown node are advised to increase
    InhibitDelayMaxSec even further possibly to 30 minutes.
    - Add NEWS entry about increasing InhibitDelayMaxSec and InstallOnShutdown
      changes
  * Ignore "W503 line break before binary operator"
    because it will become the best practice and breaks the build
  * Stop using ActionGroups, they interfere with apt.Cache.clear()
    causing all autoremovable packages to be handled as newly autoremovable
    ones and be removed by default. Dropping ActionGroup usage does not slow
    down the most frequent case of not having anything to upgrade a...

Changed in unattended-upgrades (Ubuntu Xenial):
status: Fix Committed → Fix Released
Balint Reczey (rbalint) wrote :

This bug has been fixed in 1.1ubuntu1.18.04.9.

Changed in unattended-upgrades (Ubuntu Bionic):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.