Bug#688428: apt times out post download when processing triggers

[Sharon Kimble]

Package: apt
Version: 0.9.7.4
Severity: normal

Dear Maintainer,
When downloading updates in wheezy, apt-get always timesout in post-download
trigger workings. Then the bash prompt is shown again.

I have tried to find where the 'timeout' is configured in all the apt
configuration files without success.

I expect apt to continue and complete, and show its working as part of the
download process.

sudo apt-get install alpine
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following packages were automatically installed and are no longer required:
libnuclient4 libnussl1
Use 'apt-get autoremove' to remove them.
The following extra packages will be installed:
alpine-doc
The following NEW packages will be installed:
alpine alpine-doc
0 upgraded, 2 newly installed, 0 to remove and 0 not upgraded.
Need to get 3,571 kB of archives.
After this operation, 8,118 kB of additional disk space will be used.
Do you want to continue [Y/n]? y
Get:1 http://http.debian.net/debian/ wheezy/main alpine i386 2.02+dfsg-1.1
[3,180 kB]
Get:2 http://http.debian.net/debian/ wheezy/main alpine-doc all 2.02+dfsg-1.1
[390 kB]
Fetched 3,571 kB in 3s (970 kB/s)
[master 95ae1a1] saving uncommitted changes in /etc prior to apt run
Author: boztu <bo...@london.dlink.com>
3 files changed, 5112 insertions(+), 5001 deletions(-)
rewrite readahead.d/custom.later (77%)
Selecting previously unselected package alpine.
(Reading database ... 294225 files and directories currently installed.)
Unpacking alpine (from .../alpine_2.02+dfsg-1.1_i386.deb) ...
Selecting previously unselected package alpine-doc.
Unpacking alpine-doc (from .../alpine-doc_2.02+dfsg-1.1_all.deb) ...
Processing triggers for man-db ...
Setting up alpine (2.02+dfsg-1.1) ...
Setting up alpine-doc (2.02+dfsg-1.1) ...
Error: Timeout was reached



-- Package-specific info:

-- apt-config dump --

APT "";
APT::Architecture "i386";
APT::Build-Essential "";
APT::Build-Essential:: "build-essential";
APT::Install-Recommends "true";
APT::Install-Suggests "0";
APT::Authentication "";
APT::Authentication::TrustCDROM "true";
APT::NeverAutoRemove "";
APT::NeverAutoRemove:: "^firmware-linux.*";
APT::NeverAutoRemove:: "^linux-firmware$";
APT::NeverAutoRemove:: "^linux-image.*";
APT::NeverAutoRemove:: "^kfreebsd-image.*";
APT::NeverAutoRemove:: "^linux-restricted-modules.*";
APT::NeverAutoRemove:: "^linux-ubuntu-modules-.*";
APT::NeverAutoRemove:: "^gnumach$";
APT::NeverAutoRemove:: "^gnumach-image.*";
APT::Never-MarkAuto-Sections "";
APT::Never-MarkAuto-Sections:: "metapackages";
APT::Never-MarkAuto-Sections:: "restricted/metapackages";
APT::Never-MarkAuto-Sections:: "universe/metapackages";
APT::Never-MarkAuto-Sections:: "multiverse/metapackages";
APT::Never-MarkAuto-Sections:: "oldlibs";
APT::Never-MarkAuto-Sections:: "restricted/oldlibs";
APT::Never-MarkAuto-Sections:: "universe/oldlibs";
APT::Never-MarkAuto-Sections:: "multiverse/oldlibs";
APT::Periodic "";
APT::Periodic::Update-Package-Lists "0";
APT::Periodic::Download-Upgradeable-Packages "0";
APT::Periodic::AutocleanInterval "0";
APT::Periodic::Unattended-Upgrade "0";
APT::Update "";
APT::Update::Post-Invoke "";
APT::Update::Post-Invoke:: "touch /var/lib/apt/periodic/update-success-stamp 2>/dev/null || true";
APT::Update::Post-Invoke-Success "";
APT::Update::Post-Invoke-Success:: "[ ! -f /var/run/dbus/system_bus_socket ] || /usr/bin/dbus-send --system --dest=org.debian.apt --type=signal /org/debian/apt org.debian.apt.CacheChanged || true";
APT::Update::Post-Invoke-Success:: "/usr/bin/test -e /usr/share/dbus-1/system-services/org.freedesktop.PackageKit.service && /usr/bin/test -S /var/run/dbus/system_bus_socket && /usr/bin/gdbus call --system --dest org.freedesktop.PackageKit --object-path /org/freedesktop/PackageKit --timeout 1 --method org.freedesktop.PackageKit.StateHasChanged cache-update > /dev/null; /bin/echo > /dev/null";
APT::Archives "";
APT::Archives::MaxAge "30";
APT::Archives::MinAge "2";
APT::Archives::MaxSize "500";
APT::Architectures "";
APT::Architectures:: "i386";
APT::Compressor "";
APT::Compressor::. "";
APT::Compressor::.::Name ".";
APT::Compressor::.::Extension "";
APT::Compressor::.::Binary "";
APT::Compressor::.::Cost "1";
APT::Compressor::gzip "";
APT::Compressor::gzip::Name "gzip";
APT::Compressor::gzip::Extension ".gz";
APT::Compressor::gzip::Binary "gzip";
APT::Compressor::gzip::Cost "2";
APT::Compressor::gzip::CompressArg "";
APT::Compressor::gzip::CompressArg:: "-9n";
APT::Compressor::gzip::UncompressArg "";
APT::Compressor::gzip::UncompressArg:: "-d";
APT::Compressor::bzip2 "";
APT::Compressor::bzip2::Name "bzip2";
APT::Compressor::bzip2::Extension ".bz2";
APT::Compressor::bzip2::Binary "bzip2";
APT::Compressor::bzip2::Cost "3";
APT::Compressor::bzip2::CompressArg "";
APT::Compressor::bzip2::CompressArg:: "-9";
APT::Compressor::bzip2::UncompressArg "";
APT::Compressor::bzip2::UncompressArg:: "-d";
APT::Compressor::xz "";
APT::Compressor::xz::Name "xz";
APT::Compressor::xz::Extension ".xz";
APT::Compressor::xz::Binary "xz";
APT::Compressor::xz::Cost "4";
APT::Compressor::xz::CompressArg "";
APT::Compressor::xz::CompressArg:: "-6";
APT::Compressor::xz::UncompressArg "";
APT::Compressor::xz::UncompressArg:: "-d";
APT::Compressor::lzma "";
APT::Compressor::lzma::Name "lzma";
APT::Compressor::lzma::Extension ".lzma";
APT::Compressor::lzma::Binary "xz";
APT::Compressor::lzma::Cost "5";
APT::Compressor::lzma::CompressArg "";
APT::Compressor::lzma::CompressArg:: "--format=lzma";
APT::Compressor::lzma::CompressArg:: "-9";
APT::Compressor::lzma::UncompressArg "";
APT::Compressor::lzma::UncompressArg:: "--format=lzma";
APT::Compressor::lzma::UncompressArg:: "-d";
APT::Compressor::::Name "";
APT::Compressor::::Extension ".";
APT::Compressor::::Binary "";
APT::Compressor::::Cost "100";
APT::Compressor::::CompressArg "";
APT::Compressor::::CompressArg:: "-9";
APT::Compressor::::UncompressArg "";
APT::Compressor::::UncompressArg:: "-d";
Dir "/";
Dir::State "var/lib/apt/";
Dir::State::lists "lists/";
Dir::State::cdroms "cdroms.list";
Dir::State::mirrors "mirrors/";
Dir::State::extended_states "extended_states";
Dir::State::status "/var/lib/dpkg/status";
Dir::Cache "var/cache/apt/";
Dir::Cache::archives "archives/";
Dir::Cache::srcpkgcache "srcpkgcache.bin";
Dir::Cache::pkgcache "pkgcache.bin";
Dir::Etc "etc/apt/";
Dir::Etc::sourcelist "sources.list";
Dir::Etc::sourceparts "sources.list.d";
Dir::Etc::vendorlist "vendors.list";
Dir::Etc::vendorparts "vendors.list.d";
Dir::Etc::main "apt.conf";
Dir::Etc::netrc "auth.conf";
Dir::Etc::parts "apt.conf.d";
Dir::Etc::preferences "preferences";
Dir::Etc::preferencesparts "preferences.d";
Dir::Etc::trusted "trusted.gpg";
Dir::Etc::trustedparts "trusted.gpg.d";
Dir::Bin "";
Dir::Bin::methods "/usr/lib/apt/methods";
Dir::Bin::solvers "";
Dir::Bin::solvers:: "/usr/lib/apt/solvers";
Dir::Bin::dpkg "/usr/bin/dpkg";
Dir::Bin::bzip2 "/bin/bzip2";
Dir::Bin::xz "/usr/bin/xz";
Dir::Media "";
Dir::Media::MountPath "/media/cdrom";
Dir::Log "var/log/apt";
Dir::Log::Terminal "term.log";
Dir::Log::History "history.log";
Dir::Ignore-Files-Silently "";
Dir::Ignore-Files-Silently:: "~$";
Dir::Ignore-Files-Silently:: "\.disabled$";
Dir::Ignore-Files-Silently:: "\.bak$";
Dir::Ignore-Files-Silently:: "\.dpkg-[a-z]+$";
Dir::Ignore-Files-Silently:: "\.save$";
Dir::Ignore-Files-Silently:: "\.orig$";
Acquire "";
Acquire::cdrom "";
Acquire::cdrom::mount "/media/cdrom";
Acquire::http "";
Acquire::http::Pipeline-Depth "0";
Acquire::Languages "";
Acquire::Languages:: "en";
Acquire::Languages:: "none";
DPkg "";
DPkg::Pre-Invoke "";
DPkg::Pre-Invoke:: "if [ -x /usr/bin/etckeeper ]; then etckeeper pre-install; fi";
DPkg::Post-Invoke "";
DPkg::Post-Invoke:: "if [ -x /usr/bin/etckeeper ]; then etckeeper post-install; fi";
DPkg::Post-Invoke:: "/usr/bin/test -e /usr/share/dbus-1/system-services/org.freedesktop.PackageKit.service && /usr/bin/test -S /var/run/dbus/system_bus_socket && /usr/bin/gdbus call --system --dest org.freedesktop.PackageKit --object-path /org/freedesktop/PackageKit --timeout 1 --method org.freedesktop.PackageKit.StateHasChanged cache-update > /dev/null; /bin/echo > /dev/null";
DPkg::Post-Invoke:: "test -f /var/run/med-config.usermenu && if [ -x /usr/sbin/blend-update-usermenus ] ; then /usr/sbin/blend-update-usermenus med ; fi ; rm -f /var/run/med-config.usermenu";
DPkg::Post-Invoke:: "x=/usr/bin/iceweasel;[ -x $x ]&&/usr/sbin/update-alternatives --set x-www-browser $x||true";
DPkg::Post-Invoke:: "if [ -d /var/lib/update-notifier ]; then touch /var/lib/update-notifier/dpkg-run-stamp; fi; if [ -e /var/lib/update-notifier/updates-available ]; then echo > /var/lib/update-notifier/updates-available; fi ";
DPkg::Pre-Install-Pkgs "";
DPkg::Pre-Install-Pkgs:: "/usr/bin/apt-listchanges --apt || test $? -ne 10";
DPkg::Pre-Install-Pkgs:: "/usr/sbin/dpkg-preconfigure --apt || true";
DPkg::Tools "";
DPkg::Tools::Options "";
DPkg::Tools::Options::/usr/bin/apt-listchanges "";
DPkg::Tools::Options::/usr/bin/apt-listchanges::Version "2";
RPM "";
RPM::Pre-Invoke "";
RPM::Pre-Invoke:: "if [ -x /usr/bin/etckeeper ]; then etckeeper pre-install; fi";
RPM::Post-Invoke "";
RPM::Post-Invoke:: "if [ -x /usr/bin/etckeeper ]; then etckeeper post-install; fi";
Unattended-Upgrade "";
Unattended-Upgrade::Origins-Pattern "";
Unattended-Upgrade::Origins-Pattern:: "origin=Debian,archive=stable,label=Debian-Security";
CommandLine "";
CommandLine::AsString "apt-config dump";

-- (no /etc/apt/preferences present) --


-- /etc/apt/sources.list --

#

# deb cdrom:[Debian GNU/Linux 6.0.0 _Squeeze_ - Official i386 DVD Binary-1 20110205-17:27]/ squeeze contrib main

# deb cdrom:[Debian GNU/Linux 6.0.0 _Squeeze_ - Official i386 DVD Binary-1 20110205-17:27]/ squeeze contrib main


# deb http://ftp.uk.debian.org/debian/ wheezy main
# deb-src http://ftp.uk.debian.org/debian/ wheezy main

#deb http://security.debian.org/ wheezy/updates main contrib
#deb-src http://security.debian.org/ wheezy/updates main contrib

# deb http://ftp.uk.debian.org/debian/ wheezy-updates main contrib
# deb-src http://ftp.uk.debian.org/debian/ wheezy-updates main contrib

deb http://deb.opera.com/opera/ stable non-free

# deb http://www.deb-multimedia.org testing main non-free
#deb http://dl.google.com/linux/chrome/deb/ testing main
deb http://dl.google.com/linux/chrome/deb/ stable main

# deb http://ftp.uk.debian.org/debian/ wheezy non-free

# deb http://http.us.debian.org/debian/ wheezy non-free

deb http://http.debian.net/debian/ wheezy main
# deb http://security.debian.org/ wheezy/updates main

deb http://mirror.csclub.uwaterloo.ca/debian/ wheezy contrib non-free main
deb-src http://mirror.csclub.uwaterloo.ca/debian/ wheezy main

# deb http://http.us.debian.org/debian/ wheezy contrib non-free main

deb http://security.debian.org/ wheezy/updates main
deb-src http://security.debian.org/ wheezy/updates main
deb http://ppa.launchpad.net/pogo-dev/daily/ubuntu precise main
deb-src http://ppa.launchpad.net/pogo-dev/daily/ubuntu precise main


-- System Information:
Debian Release: wheezy/sid
APT prefers testing
APT policy: (500, 'testing')
Architecture: i386 (i686)

Kernel: Linux 3.2.0-3-686-pae (SMP w/1 CPU core)
Locale: LANG=en_GB.utf8, LC_CTYPE=en_GB.utf8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash

Versions of packages apt depends on:
ii debian-archive-keyring 2012.4
ii gnupg 1.4.12-4+b1
ii libapt-pkg4.12 0.9.7.4
ii libc6 2.13-35
ii libgcc1 1:4.7.1-7
ii libstdc++6 4.7.1-7

apt recommends no packages.

Versions of packages apt suggests:
pn apt-doc <none>
ii aptitude 0.6.8.1-1
ii dpkg-dev 1.16.8
ii python-apt 0.8.4
ii synaptic 0.75.12
ii xz-utils 5.1.1alpha+20120614-1

-- no debconf information


--
To UNSUBSCRIBE, email to debian-bugs-...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org

[Daniel Hartwig]

reassign -1 packagekit

On 22 September 2012 23:53, Sharon Kimble <boud...@talktalk.net> wrote:
> I expect apt to continue and complete

It has. The error you receive:

> Processing triggers for man-db ...
> Setting up alpine (2.02+dfsg-1.1) ...
> Setting up alpine-doc (2.02+dfsg-1.1) ...
> Error: Timeout was reached

is not from apt but output as a result of one of the Post-Invoke triggers.

How often do you receive such an error and is your system under
increased load when it happens?

Searching your apt conf. for the term “timeout” matches this entry:

> DPkg::Post-Invoke:: "/usr/bin/test -e /usr/share/dbus-1/system-services/org.freedesktop.PackageKit.service && /usr/bin/test -S /var/run/dbus/system_bus_socket && /usr/bin/gdbus call --system --dest org.freedesktop.PackageKit --object-path /org/freedesktop/PackageKit --timeout 1 --method org.freedesktop.PackageKit.StateHasChanged cache-update > /dev/null; /bin/echo > /dev/null";

which is calling /usr/bin/gdbus. Grepping the source of that package
(libglib2.0-bin) indicates that it does contain a “Timeout was
reached” error.

This entry is added by packagekit, so reassigning.

Regards

[Sharon Kimble]

On 23/09/12 01:33, Daniel Hartwig wrote:
> reassign -1 packagekit
>
> On 22 September 2012 23:53, Sharon Kimble <boud...@talktalk.net> wrote:
>> I expect apt to continue and complete
>
> It has. The error you receive:
>
>> Processing triggers for man-db ...
>> Setting up alpine (2.02+dfsg-1.1) ...
>> Setting up alpine-doc (2.02+dfsg-1.1) ...
>> Error: Timeout was reached
>
> is not from apt but output as a result of one of the Post-Invoke triggers.
>
> How often do you receive such an error and is your system under
> increased load when it happens?

Every time now, its just happened again with updating this morning.

>
> Searching your apt conf. for the term “timeout” matches this entry:
>
>> DPkg::Post-Invoke:: "/usr/bin/test -e /usr/share/dbus-1/system-services/org.freedesktop.PackageKit.service && /usr/bin/test -S /var/run/dbus/system_bus_socket && /usr/bin/gdbus call --system --dest org.freedesktop.PackageKit --object-path /org/freedesktop/PackageKit --timeout 1 --method org.freedesktop.PackageKit.StateHasChanged cache-update > /dev/null; /bin/echo > /dev/null";
>
> which is calling /usr/bin/gdbus. Grepping the source of that package
> (libglib2.0-bin) indicates that it does contain a “Timeout was
> reached” error.
>
> This entry is added by packagekit, so reassigning.

Fair enough, thanks.
>
> Regards
>

Sharon.
--
A taste of linux = http://www.sharons.org.uk/taste/index.html
efever = http://www.efever.blogspot.com/
efever = http://sharon04.livejournal.com/
Debian Wheezy, xfce 4.8, LibreOffice 3.5.4.2
Registered Linux user 334501

[Daniel Hartwig]

On 23 September 2012 16:57, Sharon Kimble <boud...@talktalk.net> wrote:
>> How often do you receive such an error and is your system under
>> increased load when it happens?
>
>
> Every time now, its just happened again with updating this morning.

Assuming then that the system load is not a problem.

You could investigate log files associated with dbus, packagekit, and
dmesg(1) for anything which may indicate a failure to load,
communicate, etc..

I am not familiar with those systems, so can not provide any more
specific guidance.

Regards

[Matthias Klumpp]

Hi!
This issue is really odd, because the DBus call should never ever
fail... Is DBus working properly? Can you easily reproduce the issue?
What happens if you run the hook command manually in a terminal? Does it block?
Cheers,
Matthias

2012/9/24 Daniel Hartwig <man...@gmail.com>:

[Kurt Roeckx]

On Wed, Sep 26, 2012 at 02:00:44AM +0200, Matthias Klumpp wrote:
> Hi!
> This issue is really odd, because the DBus call should never ever
> fail...

It doesn't fail, someone set the timeout to 1 second, and dbus
doesn't reply withing 1 second, so you get that error.

> Is DBus working properly?

Yes.

> Can you easily reproduce the issue?

I see it very often, but I can't reproduce it all the time.

> What happens if you run the hook command manually in a terminal?

It directly returns:
()

> Does it block?

It can't block, it has a timeout of 1 second.


Kurt

[Kurt Roeckx]

On Thu, May 02, 2013 at 08:46:37PM +0200, Kurt Roeckx wrote:
> > Does it block?
>
> It can't block, it has a timeout of 1 second.

So maybe I wasn't clear in this. But this --timeout 1 is the
problem. Note that lots of other things might be happening
on the system and it just might not be able to do do whatever
it needs to do in 1 second.


Kurt

[Matthias Klumpp]

2013/11/26 Kurt Roeckx <ku...@roeckx.be>:

> On Thu, May 02, 2013 at 08:46:37PM +0200, Kurt Roeckx wrote:
>> > Does it block?
>>
>> It can't block, it has a timeout of 1 second.
>
> So maybe I wasn't clear in this. But this --timeout 1 is the
> problem. Note that lots of other things might be happening
> on the system and it just might not be able to do do whatever
> it needs to do in 1 second.

Can someone please check if increasing the timeout fixes this issue?
Thanks!

--
I welcome VSRE emails. See http://vsre.info/

[Roberto C. Sánchez]

I just encountered this problem and it was the result of a malformed
packagekit transaction database :

roberto-pc:~# apt-get install --reinstall libapt-pkg5.0 apt apt-utils

Reading package lists... Done
Building dependency tree
Reading state information... Done

0 upgraded, 0 newly installed, 3 reinstalled, 0 to remove and 0 not upgraded.
Need to get 2,558 kB of archives.
After this operation, 0 B of additional disk space will be used.
Get:1 http://ftp.us.debian.org/debian stretch/main amd64 libapt-pkg5.0 amd64 1.4.7 [916 kB]
Get:2 http://ftp.us.debian.org/debian stretch/main amd64 apt amd64 1.4.7 [1,231 kB]
Get:3 http://ftp.us.debian.org/debian stretch/main amd64 apt-utils amd64 1.4.7 [410 kB]
Fetched 2,558 kB in 0s (49.9 MB/s)
(Reading database ... 277322 files and directories currently installed.)
Preparing to unpack .../libapt-pkg5.0_1.4.7_amd64.deb ...
Unpacking libapt-pkg5.0:amd64 (1.4.7) over (1.4.7) ...
Setting up libapt-pkg5.0:amd64 (1.4.7) ...
(Reading database ... 277322 files and directories currently installed.)
Preparing to unpack .../archives/apt_1.4.7_amd64.deb ...
Unpacking apt (1.4.7) over (1.4.7) ...
Setting up apt (1.4.7) ...
(Reading database ... 277322 files and directories currently installed.)
Preparing to unpack .../apt-utils_1.4.7_amd64.deb ...
Unpacking apt-utils (1.4.7) over (1.4.7) ...
Setting up apt-utils (1.4.7) ...
Processing triggers for libc-bin (2.24-11+deb9u1) ...
Processing triggers for man-db (2.7.6.1-2) ...
Error: Timeout was reached
roberto-pc:~# apt-get update
Ign:1 http://ftp.us.debian.org/debian stretch InRelease
Hit:2 http://security.debian.org/ stretch/updates InRelease
Hit:3 http://ftp.us.debian.org/debian stretch-updates InRelease
Hit:4 http://ftp.us.debian.org/debian stretch Release
Error: Timeout was reached
Reading package lists... Done
roberto-pc:~# /usr/lib/packagekit/packagekitd --verbose
17:55:56 PackageKit Verbose debugging enabled (on console 1)
17:55:56 PackageKit daemon shutdown set to 0 seconds
17:55:56 PackageKit clearing download cache at /var/cache/PackageKit/downloads
17:55:56 PackageKit setting config file watch on /etc/PackageKit/PackageKit.conf
17:55:56 PackageKit Trying to load : aptcc
17:55:56 PackageKit dlopening '/usr/lib/x86_64-linux-gnu/packagekit-backend/libpk_backend_aptcc.so'
17:55:57 PackageKit trying to open database '/var/lib/PackageKit/transactions.db'
17:55:57 PackageKit creating table to repair: Failed to execute statement 'SELECT * FROM transactions LIMIT 1': database disk image is malformed
Failed to load the backend: Failed to execute statement 'CREATE TABLE transactions (transaction_id TEXT PRIMARY KEY,timespec TEXT,duration INTEGER,succeeded INTEGER DEFAULT 0,role TEXT,data TEXT,description TEXT,uid INTEGER DEFAULT 0,cmdline TEXT);': table transactions already existsroberto-pc:~#
roberto-pc:~# rm -f /var/lib/PackageKit/transactions.db
roberto-pc:~# apt-get update
Ign:1 http://ftp.us.debian.org/debian stretch InRelease
Hit:2 http://security.debian.org/ stretch/updates InRelease
Hit:3 http://ftp.us.debian.org/debian stretch-updates InRelease
Hit:4 http://ftp.us.debian.org/debian stretch Release
Reading package lists... Done
roberto-pc:~# apt-get update


I got the idea to check from here:
https://fanf42.blogspot.com/2014/08/upgrading-to-ubuntu-1404-error-timeout.html

This could really use a better/more robust error message.

Regards,

-Roberto
--
Roberto C. Sánchez