upgrade error on 8.04 -> 10.04

[Michael Vogt]

Binary package hint: bind9

The automatic upgrade tester found the follow problem on a server upgrade test with all task packages installed:

...
[89.3263] bind9: Configuring bind9
apparmor_parser: Unable to replace "/usr/sbin/named". Profile version not supported by Apparmor module
 * Starting domain name service... bind9
   ...fail!
invoke-rc.d: initscript bind9, action "start" failed.
dpkg: Fehler beim Bearbeiten von bind9 (--configure):
 Unterprozess installiertes post-installation-Skript gab den Fehlerwert 1 zurück
...

Sorry for the bits of the log in german, it mans the post-installation script failed with exit status 1.

Full details can be found here:
http://people.ubuntu.com/~mvo/automatic-upgrade-testing/current/lts-server-tasks/apt-term.log
around line 2295.

I'm not sure if the apparmor_parser lines are relevant or a red-herring. The bit in the postinst is guarded by || true
and I see a bunch of similar errors in the logs. It also appears to be transient. When I log into the machine after the
upgrade I can restart bind9 just fine.

[Jamie Strandboge (jdstrand)]

Michael, I think that the apparmor message is innocuous. As mentioned, this message is caused by the apparmor_parser call, but it hits '|| true' and proceeds to restart bind9. The call to apparmor_parser fails because we have a new profile and apparmor-utils on an old kernel. To be sure that apparmor isn't getting in the way of the restart, can you check if there are any apparmor denials in the kern.log of this machine at the time that bind9 was restarted?

[Michael Vogt (mvo)]

Nothing in the logs that looks interessting:
...
Apr 7 16:02:36 ubuntu kernel: [ 27.487404] parport0: PC-style at 0x378 [PCSPP,TRISTATE]
Apr 7 16:02:36 ubuntu kernel: [ 27.581776] lp0: using parport0 (polling).
Apr 7 16:02:36 ubuntu kernel: [ 27.629248] ppdev: user-space parallel port driver
Apr 7 16:02:37 ubuntu kernel: [ 28.040258] audit(1270648957.065:3): type=1503 operation="inode_permission" requested_mask="a::" denied_mask="a::" name="/dev/tty" pid=3991 profile="/usr/sbin/cupsd" namespace="default"
Apr 7 16:10:46 ubuntu kernel: Kernel logging (proc) stopped.
Apr 7 16:10:46 ubuntu kernel: Kernel log daemon terminating.
Apr 7 16:15:12 ubuntu kernel: imklog: Cannot read proc file system, 1.
...
Failure happend around:
2010-04-07 16:17:13,454 ERROR got a error from dpkg for pkg: 'bind9': 'Unterprozess installiertes post-installation-Skript gab den Fehlerwert 1 zurück
'
2010-04-07 16:19:36,091 ERROR Exception during pm.DoInstall()
Traceback (most recent call last):
  File "/upgrade-tester/DistUpgradeView.py", line 182, in run
    res = pm.DoInstall(self.writefd)
SystemError: E:Sub-process /usr/bin/dpkg returned an error code (1)

[Jamie Strandboge (jdstrand)]

Michael, thanks for providing this information. I am going to remove the apparmor tag as this seems doesn't seem to be the cause of the problem.

[Chuck Short (zulcss)]

Ok, I was able to reproduce this. However I get the same warning with cups, dhcp, mysql, etc. When I rebooted the machine I didnt have any problems starting bind though. Ill attach the relevant logs to the bug report, but I do think its an apparmor problem.

[Jamie Strandboge (jdstrand)]

My comment #1 applies to those also (old kernel with new userspace) and the tool is stopping postinst, but rather the restart fails for some reason. Are you saying that all those daemons (cups, dhcp, mysql, etc) fail to restart?

[Jamie Strandboge (jdstrand)]

err... the tool (apparmor_parser) *isn't* stopping postinst.

[Jamie Strandboge (jdstrand)]

Discussed this with the security team and jjohansen. The conclusion re apparmor is:

1. if the profile replacement succeeds, no problem
2. if the profile replacement fails, then the process continues to run under the old profile, logging to kern.log (or audit.log if using auditd)
3. if there are no apparmor denied messages in the logs, the upgrade problem is elsewhere. If there are apparmor denied messages in the logs, it is an apparmor problem

Based on the above, this bug should not be an apparmor problem. However, it did uncover the fact that the new binary and configuration could be blocked by the old profile (but logged, always logged!), and this condition will be reviewed but does not affect this bug.

[Chuck Short (zulcss)]

I wasnt able to reproduce this. Michael, is it possible to get the /var/log/syslog when this happens?

chuck

[Michael Vogt (mvo)]

I just ran it again, modifying /etc/init.d/bind9 to set /bin/sh -x - this prevented the error because of resulting conffile prompt is set to "keep old" by default in the upgrade tester. So my test was not meaningful (other than that it did show that apparently with the config file the failure is not triggered). I re-run now with plain config.

[Michael Vogt (mvo)]

I ran it again and the error is gone.

The only change I can think of that fixed is the following bit in update-manager:

  * DistUpgrade/DistUpgradeQuirks.py:
    - stop apparmor before dpkg starts on hardy -> lucid upgrades to
      avoid potentially confusing error messages during the upgrade
      (LP: #559433)

 -- Michael Vogt <email address hidden> Mon, 12 Apr 2010 18:32:59 +0200

To double check I will run the upgrader again with this change removed.

[Michael Vogt (mvo)]

WIthout the apparmor stop change outlined above:

[89.3573] bind9: Configuring bind9^M
apparmor_parser: Unable to replace "/usr/sbin/named". Profile version not supported by Apparmor module^M^M
 * Starting domain name service... bind9^M^M
   ...fail!^M^M
invoke-rc.d: initscript bind9, action "start" failed.^M^M
[89.399] bind9-doc: Configuring bind9-doc^M
[89.4407] bind9-doc: Installed bind9-doc^M
dpkg: error processing bind9 (--configure):^M^M
 subprocess installed post-installation script returned error exit status 1^M^M

[Michael Vogt (mvo)]

Given that the workaroudn is now in place in u-m the importance can be lowered. It may however still affect people upgrading with apt-get or aptitude.

[Michael Vogt (mvo)]

And the lts-server-tasks upgrades now cleanly:
http://people.canonical.com/~mvo/automatic-upgrade-testing/2010-04-14-19:03:01/

The other one just has a conffile prompt like leftover file for /etc/default/bind9.dpkg-dist so it looks good.

[Jamie Strandboge (jdstrand)]

I'm going to mark this as 'Fix Released' for the bind9 task, since update-manager has been updated to disable apparmor and the supported upgrade option is fixed by doing this.

[Jamie Strandboge (jdstrand)]

Added linux task since it seems to not be doing what it is supposed to be doing, as discussed in comment #8. Too late to fix for Lucid (which is already worked around via update-manager anyway).

[Jamie Strandboge (jdstrand)]

Michael,

Before upgrading, can you attach to this bug the tarfile from the following command?
$ cd / ; tar -zcvf /tmp/556343.tar.gz etc/apparmor.d etc/bind

[Michael Vogt (mvo)]

Ups, sorry that I uploaded the file twice, launchpad was OOPSing on me a couple of times so I did not realize one made it through.