Unattended upgrade fails with "Error in function"

[Marius Gedminas]

This is the cron email I received today:

    From: root <email address hidden>
    To: <email address hidden>
    Subject: unattended-upgrades result for 'iv-4.pov.lt': 'False'
    Date: Wed, 4 Oct 2017 03:40:19 +0300 (EEST)

    Unattended upgrade returned: False

    Packages that attempted to upgrade:
     ca-certificates libidn11 libnss3 libnss3-nssdb

    Package installation log:
    Error in function:

    Unattended-upgrades log:
    Initial blacklisted packages:
    Starting unattended upgrades script
    Allowed origins are: ['o=Ubuntu,a=trusty-security', 'o=UbuntuESM,a=trusty', 'o=Ubuntu,a=trusty-security', 'o=Ubuntu,a=trusty-updates', 'origin=LP-PPA-pov,suite=trusty']
    Packages that will be upgraded: ca-certificates libidn11 libnss3 libnss3-nssdb
    Writing dpkg log to '/var/log/unattended-upgrades/unattended-upgrades-dpkg_2017-10-04_03:40:17.411277.log'
    Installing the upgrades failed!
    error message: 'installArchives() failed'
    dpkg returned a error! See '/var/log/unattended-upgrades/unattended-upgrades-dpkg_2017-10-04_03:40:17.411277.log' for details
    Packages that are auto removed: ''
    Packages auto-removed

The named log file, var/log/unattended-upgrades/unattended-upgrades-dpkg_2017-10-04_03:40:17.411277.log contains only this:

    Error in function:

That's it.

Now given that ca-certificates is involved, I suspect this may be related to non-ASCII filenames (see bug 1554365), but unlike that bug, here the upgrade fails instead of succeeding, and the actual error is not shown anywhere.

ProblemType: Bug
DistroRelease: Ubuntu 14.04
Package: unattended-upgrades 0.82.1ubuntu2.5
Uname: Linux 2.6.32-042stab124.2 x86_64
ApportVersion: 2.14.1-0ubuntu3.25
Architecture: amd64
Date: Wed Oct 4 18:54:54 2017
PackageArchitecture: all
ProcEnviron:
 LC_CTYPE=lt_LT.UTF-8
 TERM=xterm-256color
 PATH=(custom, no user)
 LANG=lt_LT.UTF-8
 SHELL=/bin/bash
SourcePackage: unattended-upgrades
UpgradeStatus: No upgrade log present (probably fresh install)

[Marius Gedminas (mgedmin)]

This happened again this morning, on a different VPS, while trying to upgrade curl libcurl3 libcurl3-gnutls linux-libc-dev.

My guess that this had something to do with ca-certificates upgade printing non-ASCII strings to the output was proven wrong.

[Brian Murray (brian-murray)]

Can you try manually running the upgrade with the verbose switch? e.g. 'unattended-upgrade -v'.

[Launchpad Janitor (janitor)]

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

[Marius Gedminas (mgedmin)]

This happened again, while trying to upgrade libpq-dev libpq5 postgresql-9.3 postgresql-client-9.3.

Running `unattended-upgrade -v` over an interactive SSH session succeeded.

I'm not sure what's different. Locale? The successful installation log contains some non-ASCII characters, specifically dpkg's

    (Skaitoma duomenų bazė ... 53857 files and directories currently installed.)

But if that were the problem, then every upgrade would fail, not just some of them. (Besides, if the locale were missing from the cron environment, dpkg wouldn't be using translations.)

[Marius Gedminas (mgedmin)]

This happened again. Can I tweak some config file to enable verbose mode for unattended-upgrades and see if it'll fail when run from cron tomorrow night?

[Brian Murray (brian-murray)]

Try running it with the --debug switch.

1514 parser.add_option("-d", "--debug",
1515 action="store_true", default=False,
1516 help=_("print debug messages"))

[Marius Gedminas (mgedmin)]

The thing is, whenever I run it interactively over ssh, unattended-upgrade succeeds. It's only the cron job that fails.

If there's no separate config file, I'll edit /etc/cron.daily/apt directly. (This server is still on Ubuntu 14.04 LTS).

[Marius Gedminas (mgedmin)]

(By reading that script I've discovered the existence of APT::Periodic::Verbose. We'll see what happens next morning with this set to "1"!)

[Marius Gedminas (mgedmin)]

The good news is the problem is reproducible.

The bad news is APT::Periodic::Verbose "1" doesn't make unattended-upgrade produce any more output in its failure email:

    Unattended upgrade returned: False

    Packages that attempted to upgrade:
     dh-apparmor libapparmor1 python3-update-manager update-manager-core

    Package installation log:
    Error in function:

    Unattended-upgrades log:
    Initial blacklisted packages:
    Starting unattended upgrades script
    Allowed origins are: ['o=Ubuntu,a=trusty-security', 'o=UbuntuESM,a=trusty', 'o=Ubuntu,a=trusty-security', 'o=Ubuntu,a=trusty-updates', 'origin=LP-PPA-pov,suite=trusty']
    Packages that will be upgraded: dh-apparmor libapparmor1 python3-update-manager update-manager-core
    Writing dpkg log to '/var/log/unattended-upgrades/unattended-upgrades-dpkg_2018-02-13_03:07:51.796037.log'
    Installing the upgrades failed!
    error message: 'installArchives() failed'
    dpkg returned a error! See '/var/log/unattended-upgrades/unattended-upgrades-dpkg_2018-02-13_03:07:51.796037.log' for details
    Packages that are auto removed: ''
    Packages auto-removed

Which is exactly the same thing I saw yesterday. I think I see my mistake: I should've set APT::Periodic::Verbose to "3" to have the cron script pass -d to unattended-upgrade! D'oh!

On the other hand I got an extra email from cron.daily saying

    /etc/cron.daily/apt:
    verbose level 1
    sleeping for 280 seconds
    check_stamp: interval=86400, now=1518559200, stamp=1518472800, delta=86400 (sec)
    apt-key net-update (failure)
    download updated metadata (success).
    send dbus signal (success)
    check_stamp: interval=0
    download upgradable (not run)
    check_stamp: interval=86400, now=1518559200, stamp=1518472800, delta=86400 (sec)
    unattended-upgrade (success)
    check_stamp: interval=0
    autoclean (not run)
    aged: ctime <30 and mtime <30 and ctime>2 and mtime>2
    end remove by archive size: size=24256 < 512000

The "apt-key net-update (failure)" line is intriguing, but seems to be unrelated.

I've bumped APT::Periodic::Verbose to "3" now and will see what happens next morning.

[Marius Gedminas (mgedmin)]

Well, I got the debug output this time (a whole megabyte of it, split in two different emails), but unattended-upgrades succeeded, so I still don't know what the original problem was.

[Yurii Oleynikov (yuolvka)]

For me this happened in 14.04.
I've found that root cause was PATH environment variable that lack /sbin and /usr/sbin

[Marius Gedminas (mgedmin)]

Yurii: can you clarify how that broke unattended upgrades?

I also don't see how a cron script might get different PATH values from one day to the other.
I just had another instance of this bug on a third Ubuntu 14.04 LTS server (this one a physical machine, not a VPS) where unattended-upgrades worked fine before. And on that machine

    # cat /proc/$(pidof cron)/environ | tr '\0' '\n' | grep PATH
    PATH=/usr/local/sbin:/usr/local/bin:/usr/bin:/usr/sbin:/sbin:/bin

looks fine to me.

[Marius Gedminas (mgedmin)]

This is a very annoying bug. Last morning unattended-upgrade failed on a machine, so I set APT::Periodic::Verbose to "3" and this morning I got a very verbose email showing that it succeeded.