Merge lp:~didrocks/ubuntu-release-upgrader/add_telemetry into lp:ubuntu-release-upgrader

[Didier Roche-Tolomelli]

Add upgrade telemetry data for later collect in ubuntu-report.

Add upgrade telemetry data for later collect in ubuntu-report.

This was tested with 17.04 -> 18.04 upgrade, in text mode, GTK3 and KDE.

[Brian Murray (brian-murray)]

Keep in mind that it is possible to from one release to multiple releases e.g. from xenial to artful or bionic. So without knowing the database structure I think it would make sense to also record the "To" release. You can find this in DistUpgradeController.py.

I'm also curious about how this information will be used because the use cases might benefit from gathering additional information like the version of release upgrader being used or environmental variables set.

Otherwise there are a couple of typos and one nitpick to have a look at.

review: Needs Information

[Didier Roche-Tolomelli (didrocks)]

Thanks for the review!
There isn't a fixed database structure schema. However, keep in mind that ubuntu-report gather this results (as well as installers one) under some subfields on the json, alongside collecting a lot of others information.
So basically, we have the "To" and a lot of other details. Moreinfo on https://github.com/ubuntu/ubuntu-report.

For now, we collect those details, similarly than for ubiquity, and we'll organize them next cycle if nobody on IS step up first.

Typos fixed and pushed. Thanks!

[lp:~didrocks/ubuntu-release-upgrader/add_telemetry]

3132. By Didier Roche-Tolomelli on 2018-05-11

Fix some typos

3133. By Didier Roche-Tolomelli on 2018-05-18

Use uptime time instead of time.time(), which is sensitive to system
clock reset by NTP or others…

3134. By Didier Roche-Tolomelli on 2018-05-18

Fetch if users enabled third party repos before upgrade

3135. By Didier Roche-Tolomelli on 2018-05-18

Fetch original install media

[Brian Murray (brian-murray)]

This looks good to me to merge and upload after the one change is made.

While this may be more useful for the failure case you might consider including what components (-updates, -security, main, universe, etc...) are enabled on the system that was upgraded. Here's an example from an upgrade log file.

2018-05-12 20:32:36,997 DEBUG found components: {'bionic-updates': {'main', 'universe', 'multiverse', 'restricted'}, 'bionic-security': {'main', 'universe', 'multiverse', 'restricted'}, 'bionic': {'main', 'universe', 'multiverse', 'restricted'}}

[Didier Roche-Tolomelli (didrocks)]

We don't want to include the enabled components for now, but thanks for the suggestion! I'll fix the current uptime comment.

Thanks again for the review :)

[Brian Murray (brian-murray)]

review: Approve

[Didier Roche-Tolomelli (didrocks)]

Tested artful -> bionic upgrade with this code and it reports the expected telemetry data.

review: Approve

=== modified file 'DistUpgrade/DistUpgradeController.py'
--- DistUpgrade/DistUpgradeController.py	2018-03-16 17:56:15 +0000
+++ DistUpgrade/DistUpgradeController.py	2018-05-18 10:01:29 +0000
@@ -33,6 +33,7 @@
 import copy
 from configparser import NoOptionError
 from configparser import ConfigParser as SafeConfigParser
+from .telemetry import get as get_telemetry
 from .utils import (country_mirror,
                     url_downloadable,
                     check_and_fix_xbit,
@@ -45,14 +46,7 @@
 from string import Template
 from urllib.parse import urlsplit
 
-from .DistUpgradeView import (
-    STEP_PREPARE,
-    STEP_MODIFY_SOURCES,
-    STEP_FETCH,
-    STEP_INSTALL,
-    STEP_CLEANUP,
-    STEP_REBOOT,
-)
+from .DistUpgradeView import Step
 from .DistUpgradeCache import MyCache
 from .DistUpgradeConfigParser import DistUpgradeConfig
 from .DistUpgradeQuirks import DistUpgradeQuirks
@@ -866,6 +860,7 @@
                                "'software-properties' tool or "
                                "your package manager."
                                ))
+        get_telemetry().set_using_third_party_sources(self.sources_disabled)
         return True
 
     def _logChanges(self):
@@ -1760,7 +1755,7 @@
     def fullUpgrade(self):
         # sanity check (check for ubuntu-desktop, brokenCache etc)
         self._view.updateStatus(_("Checking package manager"))
-        self._view.setStep(STEP_PREPARE)
+        self._view.setStep(Step.PREPARE)
 
         if not self.prepare():
             logging.error("self.prepare() failed")
@@ -1829,7 +1824,7 @@
             self.abort()
 
         # update sources.list
-        self._view.setStep(STEP_MODIFY_SOURCES)
+        self._view.setStep(Step.MODIFY_SOURCES)
         self._view.updateStatus(_("Updating repository information"))
         if not self.updateSourcesList():
             self.abort()
@@ -1901,14 +1896,14 @@
             self.abort()
 
         # fetch the stuff
-        self._view.setStep(STEP_FETCH)
+        self._view.setStep(Step.FETCH)
         self._view.updateStatus(_("Fetching"))
         if not self.doDistUpgradeFetching():
             self._enableAptCronJob()
             self.abort()
 
         # now do the upgrade
-        self._view.setStep(STEP_INSTALL)
+        self._view.setStep(Step.INSTALL)
         self._view.updateStatus(_("Upgrading"))
         if not self.doDistUpgrade():
             # run the post install scripts (for stuff like UUID conversion)
@@ -1922,7 +1917,7 @@
             sys.exit(1)
 
         # do post-upgrade stuff
-        self._view.setStep(STEP_CLEANUP)
+        self._view.setStep(Step.CLEANUP)
         self._view.updateStatus(_("Searching for obsolete software"))
         self.doPostUpgrade()
 
@@ -1935,8 +1930,9 @@
             os.unlink("/var/lib/ubuntu-release-upgrader/release-upgrade-available")
 
         # done, ask for reboot
-        self._view.setStep(STEP_REBOOT)
+        self._view.setStep(Step.REBOOT)
         self._view.updateStatus(_("System upgrade is complete."))            
+        get_telemetry().done()
         # FIXME should we look into /var/run/reboot-required here?
         if (not inside_chroot() and
             self._view.confirmRestart()):
@@ -1950,20 +1946,20 @@
     
     def doPartialUpgrade(self):
         " partial upgrade mode, useful for repairing "
-        self._view.setStep(STEP_PREPARE)
-        self._view.hideStep(STEP_MODIFY_SOURCES)
-        self._view.hideStep(STEP_REBOOT)
+        self._view.setStep(Step.PREPARE)
+        self._view.hideStep(Step.MODIFY_SOURCES)
+        self._view.hideStep(Step.REBOOT)
         self._partialUpgrade = True
         self.prepare()
         if not self.doPostInitialUpdate():
             return False
         if not self.askDistUpgrade():
             return False
-        self._view.setStep(STEP_FETCH)
+        self._view.setStep(Step.FETCH)
         self._view.updateStatus(_("Fetching"))
         if not self.doDistUpgradeFetching():
             return False
-        self._view.setStep(STEP_INSTALL)
+        self._view.setStep(Step.INSTALL)
         self._view.updateStatus(_("Upgrading"))
         if not self.doDistUpgrade():
             self._view.information(_("Upgrade complete"),
@@ -1971,7 +1967,7 @@
                                      "were errors during the upgrade "
                                      "process."))
             return False
-        self._view.setStep(STEP_CLEANUP)
+        self._view.setStep(Step.CLEANUP)
         if not self.doPostUpgrade():
             self._view.information(_("Upgrade complete"),
                                    _("The upgrade has completed but there "

=== modified file 'DistUpgrade/DistUpgradeView.py'
--- DistUpgrade/DistUpgradeView.py	2017-05-18 17:33:48 +0000
+++ DistUpgrade/DistUpgradeView.py	2018-05-18 10:01:29 +0000
@@ -21,7 +21,9 @@
 
 from .DistUpgradeGettext import gettext as _
 from .DistUpgradeGettext import ngettext
+from .telemetry import get as get_telemetry
 import apt
+from enum import Enum
 import errno
 import os
 import apt_pkg 
@@ -252,13 +254,14 @@
     def hide(self):
       pass
 
-(STEP_PREPARE,
- STEP_MODIFY_SOURCES,
- STEP_FETCH,
- STEP_INSTALL,
- STEP_CLEANUP,
- STEP_REBOOT,
- STEP_N) = range(1,8)
+class Step(Enum):
+    PREPARE = 1
+    MODIFY_SOURCES = 2
+    FETCH = 3
+    INSTALL = 4
+    CLEANUP = 5
+    REBOOT = 6
+    N = 7
 
 # Declare these translatable strings from the .ui files here so that
 # xgettext picks them up.
@@ -304,6 +307,7 @@
         4. Post upgrade stuff
         5. Complete
         """
+        get_telemetry().add_stage(step.name)
         pass
     def hideStep(self, step):
         " hide a certain step from the GUI "

=== modified file 'DistUpgrade/DistUpgradeViewGtk3.py'
--- DistUpgrade/DistUpgradeViewGtk3.py	2016-02-23 17:06:42 +0000
+++ DistUpgrade/DistUpgradeViewGtk3.py	2018-05-18 10:01:29 +0000
@@ -52,6 +52,7 @@
 from .DistUpgradeApport import run_apport, apport_crash
 
 from .DistUpgradeView import DistUpgradeView, FuzzyTimeToStr, InstallProgress, AcquireProgress
+from .telemetry import get as get_telemetry
 from .SimpleGtk3builderApp import SimpleGtkbuilderApp
 
 import gettext
@@ -70,7 +71,7 @@
         """ update is called regularly so that the gui can be redrawn """
         if text:
             self.status.set_text(text)
-        self.progress.set_fraction(step/float(self.totalSteps))
+        self.progress.set_fraction(step.value/float(self.totalSteps))
         while Gtk.events_pending():
             Gtk.main_iteration()
     def ask_cdrom_name(self):
@@ -452,6 +453,8 @@
         # check if we have a display etc
         Gtk.init_check(sys.argv)
 
+        get_telemetry().set_updater_type('GTK')
+
         try:
             locale.bindtextdomain("ubuntu-release-upgrader",localedir)
             gettext.textdomain("ubuntu-release-upgrader")
@@ -472,7 +475,7 @@
         # terminal stuff
         self.create_terminal()
 
-        self.prev_step = 0 # keep a record of the latest step
+        self.prev_step = None # keep a record of the latest step
         # we don't use this currently
         #self.window_main.set_keep_above(True)
         self.icontheme = Gtk.IconTheme.get_default()
@@ -598,44 +601,45 @@
     def updateStatus(self, msg):
         self.label_status.set_text("%s" % msg)
     def hideStep(self, step):
-        image = getattr(self,"image_step%i" % step)
-        label = getattr(self,"label_step%i" % step)
-        #arrow = getattr(self,"arrow_step%i" % step)
+        image = getattr(self,"image_step%i" % step.value)
+        label = getattr(self,"label_step%i" % step.value)
+        #arrow = getattr(self,"arrow_step%i" % step.value)
         image.hide()
         label.hide()
     def showStep(self, step):
-        image = getattr(self,"image_step%i" % step)
-        label = getattr(self,"label_step%i" % step)
+        image = getattr(self,"image_step%i" % step.value)
+        label = getattr(self,"label_step%i" % step.value)
         image.show()
         label.show()
     def abort(self):
         size = Gtk.IconSize.MENU
         step = self.prev_step
-        if step > 0:
-            image = getattr(self,"image_step%i" % step)
-            arrow = getattr(self,"arrow_step%i" % step)
+        if step:
+            image = getattr(self,"image_step%i" % step.value)
+            arrow = getattr(self,"arrow_step%i" % step.value)
             image.set_from_stock(Gtk.STOCK_CANCEL, size)
             image.show()
             arrow.hide()
     def setStep(self, step):
+        super(DistUpgradeViewGtk3, self).setStep(step)
         if self.icontheme.rescan_if_needed():
             logging.debug("icon theme changed, re-reading")
         # first update the "previous" step as completed
         size = Gtk.IconSize.MENU
         attrlist=Pango.AttrList()
         if self.prev_step:
-            image = getattr(self,"image_step%i" % self.prev_step)
-            label = getattr(self,"label_step%i" % self.prev_step)
-            arrow = getattr(self,"arrow_step%i" % self.prev_step)
+            image = getattr(self,"image_step%i" % self.prev_step.value)
+            label = getattr(self,"label_step%i" % self.prev_step.value)
+            arrow = getattr(self,"arrow_step%i" % self.prev_step.value)
             label.set_property("attributes",attrlist)
             image.set_from_stock(Gtk.STOCK_APPLY, size)
             image.show()
             arrow.hide()
         self.prev_step = step
         # show the an arrow for the current step and make the label bold
-        image = getattr(self,"image_step%i" % step)
-        label = getattr(self,"label_step%i" % step)
-        arrow = getattr(self,"arrow_step%i" % step)
+        image = getattr(self,"image_step%i" % step.value)
+        label = getattr(self,"label_step%i" % step.value)
+        arrow = getattr(self,"arrow_step%i" % step.value)
         # check if that step was not hidden with hideStep()
         if not label.get_property("visible"):
             return

=== modified file 'DistUpgrade/DistUpgradeViewKDE.py'
--- DistUpgrade/DistUpgradeViewKDE.py	2018-01-22 11:12:39 +0000
+++ DistUpgrade/DistUpgradeViewKDE.py	2018-05-18 10:01:29 +0000
@@ -62,6 +62,7 @@
 from .DistUpgradeApport import run_apport, apport_crash
 
 from .DistUpgradeView import DistUpgradeView, FuzzyTimeToStr, InstallProgress, AcquireProgress
+from .telemetry import get as get_telemetry
 
 import select
 import gettext
@@ -251,7 +252,7 @@
         """ update is called regularly so that the gui can be redrawn """
         if text:
           self.status.setText(text)
-        self.progressbar.setValue(step/float(self.totalSteps))
+        self.progressbar.setValue(step.value/float(self.totalSteps))
         QApplication.processEvents()
 
     def ask_cdrom_name(self):
@@ -560,6 +561,8 @@
     """KDE frontend of the distUpgrade tool"""
     def __init__(self, datadir=None, logdir=None):
         DistUpgradeView.__init__(self)
+
+        get_telemetry().set_updater_type('KDE')
         # silence the PyQt4 logger
         logger = logging.getLogger("PyQt4")
         logger.setLevel(logging.INFO)
@@ -613,7 +616,7 @@
         self.window_main.setParent(self)
         self.window_main.show()
 
-        self.prev_step = 0 # keep a record of the latest step
+        self.prev_step = None # keep a record of the latest step
 
         self._opCacheProgress = KDEOpProgress(self.window_main.progressbar_cache, self.window_main.progress_text)
         self._acquireProgress = KDEAcquireProgressAdapter(self)
@@ -733,15 +736,15 @@
         self.window_main.label_status.setText(msg)
 
     def hideStep(self, step):
-        image = getattr(self.window_main,"image_step%i" % step)
-        label = getattr(self.window_main,"label_step%i" % step)
+        image = getattr(self.window_main,"image_step%i" % step.value)
+        label = getattr(self.window_main,"label_step%i" % step.value)
         image.hide()
         label.hide()
 
     def abort(self):
         step = self.prev_step
-        if step > 0:
-            image = getattr(self.window_main,"image_step%i" % step)
+        if step:
+            image = getattr(self.window_main,"image_step%i" % step.value)
             cancelIcon = _icon("dialog-cancel",
                                fallbacks=["/usr/share/icons/oxygen/16x16/actions/dialog-cancel.png",
                                           "/usr/lib/kde4/share/icons/oxygen/16x16/actions/dialog-cancel.png",
@@ -750,6 +753,7 @@
             image.show()
 
     def setStep(self, step):
+        super(DistUpgradeViewKDE , self).setStep(step)
         okIcon = _icon("dialog-ok",
                        fallbacks=["/usr/share/icons/oxygen/16x16/actions/dialog-ok.png",
                                   "/usr/lib/kde4/share/icons/oxygen/16x16/actions/dialog-ok.png",
@@ -760,15 +764,15 @@
                                      "/usr/share/icons/crystalsvg/16x16/actions/1rightarrow.png"])
 
         if self.prev_step:
-            image = getattr(self.window_main,"image_step%i" % self.prev_step)
-            label = getattr(self.window_main,"label_step%i" % self.prev_step)
+            image = getattr(self.window_main,"image_step%i" % self.prev_step.value)
+            label = getattr(self.window_main,"label_step%i" % self.prev_step.value)
             image.setPixmap(okIcon.pixmap(16, 16))
             image.show()
             ##arrow.hide()
         self.prev_step = step
         # show the an arrow for the current step and make the label bold
-        image = getattr(self.window_main,"image_step%i" % step)
-        label = getattr(self.window_main,"label_step%i" % step)
+        image = getattr(self.window_main,"image_step%i" % step.value)
+        label = getattr(self.window_main,"label_step%i" % step.value)
         image.setPixmap(arrowIcon.pixmap(16, 16))
         image.show()
         label.setText("<b>" + label.text() + "</b>")

=== modified file 'DistUpgrade/DistUpgradeViewNonInteractive.py'
--- DistUpgrade/DistUpgradeViewNonInteractive.py	2016-10-10 18:05:08 +0000
+++ DistUpgrade/DistUpgradeViewNonInteractive.py	2018-05-18 10:01:29 +0000
@@ -36,6 +36,7 @@
 from subprocess import PIPE, Popen
 
 from .DistUpgradeView import DistUpgradeView, InstallProgress, AcquireProgress
+from .telemetry import get as get_telemetry
 from .DistUpgradeConfigParser import DistUpgradeConfig
 
 
@@ -251,6 +252,7 @@
     " non-interactive version of the upgrade view "
     def __init__(self, datadir=None, logdir=None):
         DistUpgradeView.__init__(self)
+        get_telemetry().set_updater_type('NonInteractive')
         self.config = DistUpgradeConfig(".")
         self._acquireProgress = NonInteractiveAcquireProgress()
         self._installProgress = NonInteractiveInstallProgress(logdir)
@@ -286,6 +288,7 @@
         4. Post upgrade stuff
         5. Complete
         """
+        super(DistUpgradeViewNonInteractive, self).setStep(step)
         pass
     def confirmChanges(self, summary, changes, demotions, downloadSize,
                        actions=None, removal_bold=True):

=== modified file 'DistUpgrade/DistUpgradeViewText.py'
--- DistUpgrade/DistUpgradeViewText.py	2016-04-22 19:33:04 +0000
+++ DistUpgrade/DistUpgradeViewText.py	2018-05-18 10:01:29 +0000
@@ -36,6 +36,7 @@
     ENCODING,
     InstallProgress,
     )
+from .telemetry import get as get_telemetry
 import apt.progress
 
 import gettext
@@ -88,7 +89,7 @@
     def update(self, text, step):
         """ update is called regularly so that the gui can be redrawn """
         if text:
-          print("%s (%f)" % (text, step/float(self.totalSteps)*100))
+          print("%s (%f)" % (text, step.value/float(self.totalSteps)*100))
     def ask_cdrom_name(self):
         return (False, "")
     def change_cdrom(self):
@@ -101,6 +102,7 @@
     def __init__(self, datadir=None, logdir=None):
         # indicate that we benefit from using gnu screen
         self.needs_screen = True
+        get_telemetry().set_updater_type('Text')
         # its important to have a debconf frontend for
         # packages like "quagga"
         if "DEBIAN_FRONTEND" not in os.environ:
@@ -116,7 +118,7 @@
         except Exception as e:
           logging.warning("Error setting locales (%s)" % e)
 
-        self.last_step = 0 # keep a record of the latest step
+        self.last_step = None # keep a record of the latest step
         self._opCacheProgress = apt.progress.text.OpProgress()
         self._acquireProgress = TextAcquireProgress()
         self._cdromProgress = TextCdromProgressAdapter()
@@ -162,6 +164,7 @@
       print()
       print(_("Aborting"))
     def setStep(self, step):
+      super(DistUpgradeViewText, self).setStep(step)
       self.last_step = step
     def showDemotions(self, summary, msg, demotions):
         self.information(summary, msg, 

=== added file 'DistUpgrade/telemetry.py'
--- DistUpgrade/telemetry.py	1970-01-01 00:00:00 +0000
+++ DistUpgrade/telemetry.py	2018-05-18 10:01:29 +0000
@@ -0,0 +1,101 @@
+# -*- coding: utf-8; Mode: Python; indent-tabs-mode: nil; tab-width: 4 -*-
+
+# Copyright (C) 2018 Canonical Ltd.
+#
+# Functions useful for the final install.py script and for ubiquity
+# plugins to use
+#
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; either version 2 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
+
+
+import logging
+import json
+import os
+import stat
+import subprocess
+
+
+def get():
+    """Return a singleton _Telemetry instance."""
+    if _Telemetry._telemetry is None:
+        _Telemetry._telemetry = _Telemetry()
+    return _Telemetry._telemetry
+
+
+class _Telemetry():
+
+    _telemetry = None
+
+    def __init__(self):
+        self._metrics = {}
+        self._stages_hist = {}
+        self._start_time = self._get_current_uptime()
+        self._metrics["From"] = subprocess.Popen(
+            ["lsb_release", "-r", "-s"], stdout=subprocess.PIPE,
+            universal_newlines=True).communicate()[0].strip()
+        self.add_stage('start')
+        self._dest_path = '/var/log/upgrade/telemetry'
+        try:
+            with open('/var/log/installer/media-info') as f:
+                self._metrics['InstallMedia'] = f.readline()
+        except FileNotFoundError:
+            pass
+
+    def _get_current_uptime(self):
+        """Get current uptime info. None if we couldn't fetch it."""
+        uptime = None
+        try:
+            with open('/proc/uptime') as f:
+                uptime = float(f.read().split()[0])
+        except (FileNotFoundError, OSError, ValueError) as e:
+            logging.warning("Exception while fetching current uptime: " + str(e))
+        return uptime
+
+    def add_stage(self, stage_name):
+        """Record installer stage with current time"""
+        now = self._get_current_uptime()
+        if self._start_time is None or now is None:
+            return
+        self._stages_hist[int(now-self._start_time)] = stage_name
+
+    def set_updater_type(self, updater_type):
+        """Record updater type"""
+        self._metrics['Type'] = updater_type
+
+    def set_using_third_party_sources(self, using):
+        """Record if the user had third party sources"""
+        self._metrics['ThirdPartySources'] = using
+
+    def done(self):
+        """Close telemetry collection
+
+        Save to destination file"""
+
+        self._metrics['Stages'] = self._stages_hist
+
+        target_dir = os.path.dirname(self._dest_path)
+        try:
+            if not os.path.exists(target_dir):
+                os.makedirs(target_dir)
+            with open(self._dest_path, 'w') as f:
+                json.dump(self._metrics, f)
+            os.chmod(self._dest_path,
+                     stat.S_IRUSR | stat.S_IWUSR |
+                     stat.S_IRGRP | stat.S_IROTH)
+        except OSError as e:
+            logging.warning("Exception while storing telemetry data: " +
+                            str(e))
+
+# vim:ai:et:sts=4:tw=80:sw=4:

=== modified file 'debian/changelog'
--- debian/changelog	2018-05-02 19:43:50 +0000
+++ debian/changelog	2018-05-18 10:01:29 +0000
@@ -1,3 +1,9 @@
+ubuntu-release-upgrader (1:18.04.19) UNRELEASED; urgency=medium
+
+  * Add upgrade telemetry information (LP: #1755456)
+
+ -- Didier Roche <[e-mail]>  Thu, 03 May 2018 15:55:34 +0200
+
 ubuntu-release-upgrader (1:18.04.18) bionic; urgency=medium
 
   * data/removal_blacklist.cfg: Drop unity, ubuntu-gnome-desktop, and