Debian Cron Task – ‘apt-get -y upgrade’ Runs but Does Not Upgrade System

aptcrondebianupdate

This server runs Debian 7 and I'm facing a big mystery.

Here are my cron tasks:

$ sudo crontab -e

42 15 * * * apt-get -y update >> /var/log/my-apt-update.txt
52 15 * * * apt-get -y upgrade >> /var/log/my-apt-upgrade.txt

I added the ">> /var/log/my-apt-upgrade.txt" part because I try to understand why my system never gets upgraded.

The cron tasks run. Everyday I have these lines in /var/log/syslog:

Nov 14 15:42:01 myhostname /USR/SBIN/CRON[3374]: (root) CMD (apt-get -y update >> /var/log/my-apt-update.txt)
Nov 14 15:52:01 myhostname /USR/SBIN/CRON[3394]: (root) CMD (apt-get -y upgrade >> /var/log/my-apt-upgrade.txt)

And /var/log/my-apt-upgrade.txt has paragraphs like this (I only show the last two days):

Reading package lists...
Building dependency tree...
Reading state information...
The following packages will be upgraded:
  file libmagic1
2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 0 B/256 kB of archives.
After this operation, 110 kB disk space will be freed.
Reading package lists...
Building dependency tree...
Reading state information...
The following packages will be upgraded:
  file libmagic1
2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 0 B/256 kB of archives.
After this operation, 110 kB disk space will be freed.

As you can see, the packages "file" and "libmagic1" should have been upgraded the first day. But they weren't. So the second day, they're mentioned again. But not upgraded.

And today, if I run

$ sudo apt-get -y upgrade

the packages "file" and "libmagic1" are mentioned again and they get upgraded (finally).

So, as you can see, I can upgrade manually. But these packages should have been upgraded earlier when the cron task ran.

Any clue about this mystery?

Addition Sat Nov 15 11:48:

here's what appears in my /var/log/apt/history.log around the time of the cron jobs.

Start-Date: 2014-11-13  15:52:03
Commandline: apt-get -y upgrade
Upgrade: file:amd64 (5.11-2+deb7u5, 5.11-2+deb7u6), libmagic1:amd64 (5.11-2+deb7u5, 5.11-2+deb7u6)
Error: Sub-process /usr/bin/dpkg returned an error code (2)
End-Date: 2014-11-13  15:52:03

Start-Date: 2014-11-14  15:52:03
Commandline: apt-get -y upgrade
Upgrade: file:amd64 (5.11-2+deb7u5, 5.11-2+deb7u6), libmagic1:amd64 (5.11-2+deb7u5, 5.11-2+deb7u6)
Error: Sub-process /usr/bin/dpkg returned an error code (2)
End-Date: 2014-11-14  15:52:03

The same kind of message occurs in the /var/log/apt/history.log for different packages.
For example, earlier this month, the "wget" package needed some update (I had tried with the -qq option this time but this option doesn't seem to make any difference).

Start-Date: 2014-11-03  15:52:02
Commandline: apt-get -y -qq upgrade
Upgrade: wget:amd64 (1.13.4-3+deb7u1, 1.13.4-3+deb7u2)
Error: Sub-process /usr/bin/dpkg returned an error code (2)
End-Date: 2014-11-03  15:52:02

Start-Date: 2014-11-04  15:52:02
Commandline: apt-get -y -qq upgrade
Upgrade: wget:amd64 (1.13.4-3+deb7u1, 1.13.4-3+deb7u2)
Error: Sub-process /usr/bin/dpkg returned an error code (2)
End-Date: 2014-11-04  15:52:03

Start-Date: 2014-11-05  15:52:03
Commandline: apt-get -y -qq upgrade
Upgrade: wget:amd64 (1.13.4-3+deb7u1, 1.13.4-3+deb7u2)
Error: Sub-process /usr/bin/dpkg returned an error code (2)
End-Date: 2014-11-05  15:52:03

Best Answer

It seems I found the cause of the problem.

To detect the error, I had to catch stderr in my custom log. It turned out it was useful to do that because some errors were not mailed to root and weren't written in other logs either.

To catch stderr in my log, I first changed the cron task to:

52 15 * * * apt-get -y upgrade >> /var/log/my-apt-upgrade.txt 2>&1

Today the package "wlibgcrypt11" was to be updated. This time, my log caught an error. It was more explicit than the vague error message that had appeared earlier in /var/log/apt/history.log.

In /var/log/my-apt-upgrade.txt today:

Reading package lists...
Building dependency tree...
Reading state information...
The following packages will be upgraded:
  libgcrypt11
debconf: unable to initialize frontend: Dialog
debconf: (TERM is not set, so the dialog frontend is not usable.)
debconf: falling back to frontend: Readline
debconf: unable to initialize frontend: Readline
debconf: (This frontend requires a controlling tty.)
debconf: falling back to frontend: Teletype
dpkg-preconfigure: unable to re-open stdin: 
1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 0 B/300 kB of archives.
After this operation, 35.8 kB of additional disk space will be used.
dpkg: warning: 'ldconfig' not found in PATH or not executable
dpkg: warning: 'start-stop-daemon' not found in PATH or not executable
dpkg: error: 2 expected programs not found in PATH or not executable
Note: root's PATH should usually contain /usr/local/sbin, /usr/sbin and /sbin
E: Sub-process /usr/bin/dpkg returned an error code (2)

So it was a PATH error.

The root's PATH on my system contains all the required directories. So does the secure_path variable in visudo. That's why everything works when I run sudo apt-get manually.

But cron doesn't set the environment variables. So I added a PATH environment variable for each of the cron tasks.

$ sudo crontab -e

22 16 * * * PATH='/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin' apt-get -y update >> /var/log/my-new-apt-update.txt 2>&1
32 16 * * * PATH='/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin' apt-get -y upgrade >> /var/log/my-new-apt-upgrade.txt 2>&1

And it worked! The package was successfully updated by the cron task.

Related Topic