ordering code may mark a package for configure before its unpacked

And my screenlog

Thanks for your report.

From term.log
===
Unpacking replacement initscripts ...
Processing triggers for man-db ...
Processing triggers for ureadahead ...
dpkg: error processing dpkg (--configure):
 package dpkg is already installed and configured
Errors were encountered while processing:
 dpkg
===

This is the same problem detected by auto upgrade testing.

Failure in jenkins
https://jenkins.qa.ubuntu.com/job/precise-upgrade-lucid-desktop/14/ARCH=amd64,LTS=lts,PROFILE=ubuntu,label=upgrade-test/

Last failure Feb. 2nd, not always reproducible

Looks to be the same as bug #291482, fwiw. Colin, does backporting the new ordering code from precise apt to oneiric fix this bug as well?

this was reported for lucid->precise upgrades, so ignore my comments about backporting fixes to oneiric.

I switched the auto-upgrade-tester over to dry-run mode with apt_pkg.config.set("debug::pkgDpkgPM", "1") and it shows me:

 /usr/bin/dpkg --force-overwrite --status-fd 222 --unpack --auto-deconfigure /var/cache/apt/archives/python-cairo_1.8.8-1ubuntu3_amd64.deb /var/cache/apt/archives/libcurl3-gnutls_7.22.0-3ubuntu2_amd64.deb /var/cache/apt/archives/python-pycurl_7.19.0-4ubuntu3_amd64.deb /var/cache/apt/archives/dpkg_1.16.1.2ubuntu5_amd64.deb ^M^M
 /usr/bin/dpkg --force-overwrite --status-fd 224 --configure dpkg ^M^M

That does actually look ok

From a strace log:

[pid 19148] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--status-fd", "30", "--unpack", "--auto-deconfigure", "/var/cache/apt/archives/initscripts_2.88dsf-13.10ubuntu10_amd64.deb"], [/* 31 vars */]) = 0^M
...
[pid 19197] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--status-fd", "30", "--configure", "dpkg"], [/* 31 vars */]) = 0^M
dpkg: error processing dpkg (--configure):^M^M
 package dpkg is already installed and configured^M^M

The last few lines with only --unpack and --configure:

[pid 18764] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--st
atus-fd", "30", "--unpack", "--auto-deconfigure", "/var/cache/apt/archives/libpo
lkit-gobject-1-0_0.104-1_amd64.deb", "/var/cache/apt/archives/wpasupplicant_0.7.
3-6ubuntu1_amd64.deb", "/var/cache/apt/archives/isc-dhcp-common_4.1.ESV-R4-0ubun
tu1_amd64.deb", "/var/cache/apt/archives/ifupdown_0.7~beta2ubuntu6_amd64.deb", "
/var/cache/apt/archives/network-manager-gnome_0.9.2.0+git.20120126t000800.515195
9-0ubuntu4_amd64.deb", "/var/cache/apt/archives/network-manager-pptp_0.9.2.0-1ub
untu1_amd64.deb", "/var/cache/apt/archives/network-manager_0.9.2.0+git2012021618
54.8572ecf-0ubuntu4_amd64.deb", "/var/cache/apt/archives/ppp_2.4.5-5ubuntu1_amd6
4.deb"], [/* 31 vars */]) = 0
[pid 19084] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--st
atus-fd", "30", "--configure", "libdbus-glib-1-2", "libnl-3-200", "libnl-genl-3-
200", "libnl-route-3-200"], [/* 31 vars */]) = 0
[pid 19110] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--st
atus-fd", "30", "--unpack", "--auto-deconfigure", "/var/cache/apt/archives/libns
pr4_4.8.9-1ubuntu2_amd64.deb"], [/* 31 vars */]) = 0
[pid 19120] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--st
atus-fd", "30", "--configure", "libnspr4", "libnss3", "libnm-util2", "libnm-glib
4", "libpolkit-gobject-1-0"], [/* 31 vars */]) = 0
[pid 19148] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--st
atus-fd", "30", "--unpack", "--auto-deconfigure", "/var/cache/apt/archives/inits
cripts_2.88dsf-13.10ubuntu10_amd64.deb"], [/* 31 vars */]) = 0
[pid 19197] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--st
atus-fd", "30", "--configure", "dpkg"], [/* 31 vars */]) = 0

No sign of dpkg itself being unpacked before the configure *but* its clearly there in the Debug::pkgDPkgPM=1 output.

When comparing the two logs (one with debug and one without) I noticed that they start to diverge when the xserver bits
are removed. Its not quite clear yet why, I run with -o Debug::pkgDPkgProgressReporting next

The dry-run has:
/usr/bin/dpkg --force-overwrite --status-fd 96 --force-depends --force-remove-essential --remove xserver-xorg-video-tseng ^M^M
/usr/bin/dpkg --force-overwrite --status-fd 98 --unpack --auto-deconfigure /var/cache/apt/archives/xserver-xorg-video-siliconmotion_1%3a1.7.5-1build2_amd64.deb /var/cache/apt/archives/xserver-xorg-video-ati_1%3a6.14.99~git20111219.aacbd629-0ubuntu2_amd64.deb ^M^M
/usr/bin/dpkg --force-overwrite --status-fd 100 --force-depends --force-remove-essential --remove xserver-xorg-video-nv ^M^M

And the real one:
[pid 16170] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--status-fd", "30", "--force-depends", "--force-remove-essential", "--remove", "xserver-xorg-video-tseng", "xserver-xorg-video-nv", "xserver-xorg-video-chips", "xserver-xorg-video-i128", "xserver-xorg-video-ark", "xserver-xorg-video-rendition", "xserver-xorg-video-s3virge", "xserver-xorg-video-voodoo", "xserver-xorg-video-apm", "xserver-xorg-video-v4l"], [/* 31 vars */]) = 0

[pid 16176] execve("/usr/bin/dpkg", ["/usr/bin/dpkg", "--force-overwrite", "--status-fd", "30", "--unpack", "--auto-deconfigure", "/var/cache/apt/archives/xserver-xorg-video-siliconmotion_1%3a1.7.5-1build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-ati_1%3a6.14.99~git20111219.aacbd629-0ubuntu2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-mach64_6.9.0-1build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-intel_2%3a2.17.0-1ubuntu4_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-trident_1%3a1.3.4-2build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-s3_1%3a0.6.3-4build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-mga_1%3a1.4.13.dfsg-4build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-nouveau_1%3a0.0.16+git20111201+b5534a1-1build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-neomagic_1%3a1.2.5-2build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-r128_6.8.1-5build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-cirrus_1%3a1.3.2-4build1_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-tdfx_1%3a1.4.3-4build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-sisusb_1%3a0.9.4-2build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-vesa_1%3a2.3.0-7build2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-fbdev_1%3a0.4.2-4ubuntu2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-savage_1%3a2.3.3-1ubuntu1_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-radeon_1%3a6.14.99~git20111219.aacbd629-0ubuntu2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-vmware_1%3a11.99.901-0ubuntu1_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-openchrome_1%3a0.2.904+svn1050-1_amd64.deb", "/var/cache/apt/archives/xserver-xorg-video-sis_1%3a0.10.3-3build2_amd64.deb", "/var/cache/apt/archives/libgl1-mesa-dri_8.0.1-0ubuntu2_amd64.deb", "/var/cache/apt/archives/xserver-xorg-core_2%3a1.11.4-0ubuntu4_amd64.deb"], [/* 31 va...

And there is the error:

/usr/bin/dpkg --force-overwrite --status-fd 175 --configure dpkg ^M^M

Not a single dpkg_*.deb for unpack, just a single

Marking this critical as its a regression in the ordering code that is causing this bug.

So looking over the logs I see:

...
          PreDepends order for mountall

          Trying to SmartConfigure dpkg

            SmartConfigure dpkg (1.16.1.2ubuntu5)
...
  SmartUnPack python-pycurl (replace version 7.19.0-3 with 7.19.0-4ubuntu3)

Skipping already done dpkg
...

So that looks like the unpack later got confused by the earlier SmartConfigure.

I'm looking at the PreDepends order code and from what I can see there it looks like its assuming that any dependency will be unpacked already which is not the case for dpkg. So that code needs to either ensure that dpkg is unpacked or we need to figure out why it was not unpacked before.

The upgrade is still running but it got past the previosu failure point and dpkg is now both installed and configured.
So fingers crossed. This is probably the source of all these old bugs about dpkg not being able to configure the package.

The code in there appears to be unchanged since:
8 <email address hidden> 20040920 | Bad = !SmartConfigure(Pkg);

Feedback from someone else like Donkult would be much appreciated as this is a delicate bit of the code.

Fix is in lucid-proposed
release-upgrader-apt (0.8.16~exp12ubuntu1~upgrader2) lucid-proposed; urgency=low

  * apt-pkg/packagemanager.cc:
    - when calculating pre-dependencies ensure that both unpack and
      configure are considered (instead of only configure) LP: #927993

I have reproduced the problem with release-upgrader-apt 0.8.16~exp12ubuntu1~upgrader1 in lucid-updates and have verified that the version of release-upgrader-apt 0.8.16~exp12ubuntu1~upgrader1 and ~upgrader3 in -proposed fixes the issue.

On https://jenkins.qa.ubuntu.com/job/precise-upgrade-lucid-desktop/ runs 53 to 57 are upgrades with -proposed enabled, other jobs are with -updates

Other profiles upgraded correctly with -proposed enabled.

This bug was fixed in the package apt - 0.8.16~exp12ubuntu6

---------------
apt (0.8.16~exp12ubuntu6) precise; urgency=low

  * cherry pick from
    http://bzr.debian.org/bzr/bzr/apt/apt/debian-experimental2/:
    * apt-pkg/packagemanager.cc:
      - fix bug in predepends handling - ensure that packages that needs
        unpackaging are unpacked before they are configured (LP: #927993)
    * apt-pkg/packagemanager.cc:
      - do not try to a void a breaks if the broken package pre-depends
        on the breaker, but let dpkg auto-deconfigure it
    * apt-pkg/packagemanager.cc:
      - recheck all dependencies if we changed a package in SmartConfigure
        as this could break an earlier dependency (LP: #940396)
    * recheck dependencies in SmartUnpack after a change, too
    * add Debug::pkgAcqArchive::NoQueue to disable package downloading
 -- Michael Vogt <email address hidden> Thu, 15 Mar 2012 19:46:08 +0100