ubuntu-release-upgrader apport_crash code should filter out dpkg returning 1

[Brian Murray]

If we look at the following problem in the Ubuntu Error Tracker we can see hundreds of issues with the following duplicate signature - "SystemError ( E) Sub-process /usr/bin/dpkg returned an error code (1)".

https://errors.ubuntu.com/problem/d2dd8ddd68b15cbf2c7a6e1dea241adf4a051ac0

If we look at any specific instance of that problem (https://errors.ubuntu.com/oops/887de81c-7421-11e5-a1b7-fa163e4ccdf2) we see nothing more informative. This needs to be sorted out so that we don't keep binning crashes in that bucket and can create some actionable problems.

[Brian Murray (brian-murray)]

Looking at the ubuntu-release-upgrader package hook there is the following code:

48 if problem_type == 'Crash':
 49 tmpdir = re.compile('ubuntu-release-upgrader-\w+')
 50 tb = report.get("Traceback", None)
 51 if tb:
 52 dupe_sig = ''
 53 for line in tb.splitlines():
 54 scrub_line = tmpdir.sub('ubuntu-release-upgrader-tmpdir', line)
 55 dupe_sig += scrub_line + '\n'
 56 report["DuplicateSignature"] = dupe_sig

There is nothing abnormal there, scrubbing is just to replace the tmp path in which the ubuntu-release-upgrader ones with one that is generic enough so that upgrades from different systems will have not a unique path in the traceback.

[Brian Murray (brian-murray)]

Digging into this a bit more the release upgrader has its own crash handler in DistUpgradeApport.py and apport_crash is called from the distribution upgrade frontends. The traceback is passed to apport_crash and logged to VarLogDistupgradeMain.log. As an example if we look at bug 1497581 we can see the following in Main.log.

2015-09-19 14:33:09,165 ERROR got an error from dpkg for pkg: 'urfkill': 'subprocess installed post-installation script returned error exit status 100'
2015-09-19 14:33:09,165 DEBUG running apport_pkgfailure() urfkill: subprocess installed post-installation script returned error exit status 100
2015-09-19 14:33:09,175 ERROR got an error from dpkg for pkg: 'urfkill': 'subprocess installed post-installation script returned error exit status 100'
2015-09-19 14:33:10,386 ERROR not handled expection:
SystemError: E:Sub-process /usr/bin/dpkg returned an error code (1), E:Sub-process /usr/bin/dpkg returned an error code (1)

2015-09-19 14:33:10,386 DEBUG running apport_crash()

Calling apport_crash in this case seems unnecessary as the apport-package report about urfkill is what we really want. There is a later crash for which we would want a report.

2015-09-19 14:33:33,468 ERROR not handled expection:
Traceback (most recent call last):

  File "/tmp/ubuntu-release-upgrader-e1xtx4y9/DistUpgrade/DistUpgradeController.py", line 1137, in doDistUpgrade
    res = self.cache.commit(fprogress,iprogress)

  File "/tmp/ubuntu-release-upgrader-e1xtx4y9/DistUpgrade/DistUpgradeCache.py", line 267, in commit
    apt.Cache.commit(self, fprogress, iprogress)

  File "/usr/lib/python3/dist-packages/apt/cache.py", line 505, in commit
    if fetch_progress is None:

SystemError: installArchives() failed

During handling of the above exception, another exception occurred:

TypeError: wait_for_child() takes 1 positional argument but 2 were given

2015-09-19 14:33:33,468 DEBUG running apport_crash()

[Brian Murray (brian-murray)]

When fixing this it is important to make sure that the apport_pkgfailure call is creating an apport report and that is getting submitted.

[Brian Murray (brian-murray)]

Its also worth noting that apport some filtering is done of dependency problem crashes:

2015-10-16 12:50:31,715 ERROR got an error from dpkg for pkg: 'libdevmapper1.02.1': '9.90216:dependency problems - leaving unconfigured'
2015-10-16 12:50:31,716 DEBUG running apport_pkgfailure() libdevmapper1.02.1: 9.90216:dependency problems - leaving unconfigured
2015-10-16 12:50:31,716 DEBUG dpkg error because of dependency problems, not reporting against libdevmapper1.02.1
2015-10-16 12:50:31,716 ERROR got an error from dpkg for pkg: 'libdevmapper1.02.1': '9.90216:dependency problems - leaving unconfigured'
2015-10-16 12:50:51,062 ERROR got an error from dpkg for pkg: 'dmsetup': 'dependency problems - leaving unconfigured'
2015-10-16 12:50:51,062 DEBUG running apport_pkgfailure() dmsetup: dependency problems - leaving unconfigured
2015-10-16 12:50:51,063 DEBUG dpkg error because of dependency problems, not reporting against dmsetup
2015-10-16 12:50:51,063 ERROR got an error from dpkg for pkg: 'dmsetup': 'dependency problems - leaving unconfigured'
2015-10-16 12:50:51,488 ERROR got an error from dpkg for pkg: 'libcryptsetup4': 'dependency problems - leaving unconfigured'
2015-10-16 12:50:51,488 DEBUG running apport_pkgfailure() libcryptsetup4: dependency problems - leaving unconfigured
2015-10-16 12:50:51,488 DEBUG dpkg error because of dependency problems, not reporting against libcryptsetup4
2015-10-16 12:50:51,488 ERROR got an error from dpkg for pkg: 'libcryptsetup4': 'dependency problems - leaving unconfigured'
2015-10-16 12:51:06,107 ERROR got an error from dpkg for pkg: 'systemd': 'dependency problems - leaving unconfigured'
2015-10-16 12:51:06,107 DEBUG running apport_pkgfailure() systemd: dependency problems - leaving unconfigured
2015-10-16 12:51:06,107 DEBUG dpkg error because of dependency problems, not reporting against systemd

[Brian Murray (brian-murray)]

It seems to me that the dependency problems filtering actually prevents a bug report from being filed about the first failure.

[Brian Murray (brian-murray)]

I looked for any cases where dpkg returning error code 1 did not ever occur after a call to apport_pkgfailure() and could not find any. So I think filtering out Tracebacks like "SystemError: E:Sub-process /usr/bin/dpkg returned an error code (1)" is fine.