[regression] Logging in to Unity8 takes 25 seconds (the default DBus timeout)

Two threads look suspicious during the hang:

Thread 1:

#0 pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f34c8fd2b4b in QWaitCondition::wait(QMutex*, unsigned long) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#2 0x00007f34c965dc7b in ?? () from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#3 0x00007f34c961a0d5 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#4 0x00007f34c961a8a5 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#5 0x00007f34c962671d in ?? () from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#6 0x00007f34c9626875 in QDBusInterface::QDBusInterface(QString const&, QString const&, QString const&, QDBusConnection const&, QObject*) ()
   from /usr/lib/x86_64-linux-gnu/libQt5DBus.so.5
#7 0x00007f348291b12b in UCContentHub::UCContentHub(QObject*) ()
   from /usr/lib/x86_64-linux-gnu/libUbuntuToolkit.so.5
#8 0x00007f3482936598 in ?? ()
   from /usr/lib/x86_64-linux-gnu/libUbuntuToolkit.so.5
#9 0x00007f34c9e52ea1 in QQmlType::SingletonInstanceInfo::init(QQmlEngine*) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#10 0x00007f34c9eb04c5 in QV4::QmlTypeWrapper::toVariant() const ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#11 0x00007f34c9d886e6 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#12 0x00007f34c9d88844 in QV4::ExecutionEngine::toVariant(QV4::Value const&, int, bool) () from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#13 0x00007f34c9ea83ae in QQmlBinding::write(QQmlPropertyData const&, QV4::Value const&, bool, QFlags<QQmlPropertyPrivate::WriteFlag>) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#14 0x00007f34c9ea94e7 in QQmlBinding::update(QFlags<QQmlPropertyPrivate::WriteFlag>) () from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#15 0x00007f34c9eb3035 in ?? () from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#16 0x00007f34c9e3d01e in QQmlComponentPrivate::complete(QQmlEnginePrivate*, QQmlComponentPrivate::ConstructionState*) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#17 0x00007f34c9e3d0e7 in QQmlComponentPrivate::completeCreate() ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#18 0x00007f34c9e3cf50 in QQmlComponent::create(QQmlContext*) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Qml.so.5
#19 0x00007f34cb97d553 in QQuickView::continueExecute() ()
   from /usr/lib/x86_64-linux-gnu/libQt5Quick.so.5
#20 0x00007f34cb97db1d in QQuickViewPrivate::execute() ()
   from /usr/lib/x86_64-linux-gnu/libQt5Quick.so.5
#21 0x0000556b357e79c5 in ?? ()
#22 0x0000556b357e65b3 in ?? ()
#23 0x0000556b357e26c7 in ?? ()
#24 0x00007f34c85df3f1 in __libc_start_main (main=0x556b357e2600, argc=2,
    argv=0x7ffe95fdf8f8, init=<optimised out>, fini=<optimised out>,
    rtld_fini=<optimised out>, stack_end=0x7ffe95fdf8e8)
    at ../csu/libc-start.c:291
#25 0x0000556b357e2a1a in _start ()

Thread 11:

#0 pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f34c8fd2b4b in QWaitCondition::wait(QMutex*, unsigned long) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#2 0x00007f34c8fcba23 in QSemaphore::acquire(int) ()
   from /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
#3 0x...

Yep, 25 seconds is the default QDBus timeout...

http://doc.qt.io/qt-4.8/qdbusabstractinterface.html#setTimeout

Status changed to 'Confirmed' because the bug affects multiple users.

It started happening 2 days ago, with the new version of unity-system-compositor, namely silo https://bileto.ubuntu.com/#/ticket/2439 and https://code.launchpad.net/~unity-system-compositor-team/unity-system-compositor/0.9/+merge/316460

unity-system-compositor 0.9.1 (the aforementioned silo) is unlikely to be causing this, since:

1. I had a zesty system I hadn't updated in a week or so, which did not exhibit the bug. After updating only USC to 0.9.1, I still couldn't reproduce the bug. However, after doing a subsequent dist-upgrade the issue appeared, which indicates that one of the dist-upgraded packages is involved. I have uploaded the full dist-upgraded package list at: https://pastebin.canonical.com/178774/.

2. In a fully updated zesty system exhibiting the issue, downgrading USC to 0.9.0 does not fix the problem.

Yup, correct alf, verified that downgrading unity-system-compositor on xenial doesn't fix the problem

#7 0x00007f348291b12b in UCContentHub::UCContentHub(QObject*) ()

Ok, so looking at the backtrace, it must be this silo that also landed recently:

https://bileto.ubuntu.com/#/ticket/2418

MP: https://code.launchpad.net/~bzoltan/ubuntu-ui-toolkit/landing-2017-01-30/+merge/315882

and the specific code: https://code.launchpad.net/~artmello/ubuntu-ui-toolkit/ubuntu-ui-toolkit-clipboard-dbus/+merge/314072

This appears to be a start-up race between unity8 and content-hub-service.

On a fresh boot content-hub-service is not running. It gets started /during/ the first Unity8 login. But that appears to be slightly too late. Perhaps Unity8 is hanging because it already attempted the the connection to Content Hub slightly before content-hub-service had started.

If you log out then content-hub-service keeps running in the background. So your second and subsequent login is fast.

Still eagerly awaiting a release for this :)

This bug was fixed in the package ubuntu-ui-toolkit - 1.3.2184+17.04.20170306

---------------
ubuntu-ui-toolkit (1.3.2184+17.04.20170306) zesty; urgency=medium

  [ Adnane Belmadiaf ]
  * Add support for CheckBox label when set
  * Add more tests for checkbox. Fixes LP: #1333228, LP: #1442851.
  * Make sure we resets partial text input from the input method.
    Fixes LP: #1630872.
  * Fix ListItem title/subtitle alignment & elide in RTL mode.
    Fixes LP: #1665944.
  * Fix PageHeader title alignment & elide in RTL mode. Fixes LP: #1665942.
  * Fix UbuntuListView docs. Fixes LP: #1486940.
  * Add count prop to OptionSelector. Fixes LP: #1341559.
  * Replace the hardcoded color with a theme color. Fixes LP: #1664758.
  * Fix the import statement for Menu, MenuBar and MenuGroup.
    Fixes LP: #1660604.

  [ Albert Astals Cid ]
  * Fix memory leak in UCStyleHints
  * ThinDivider: Anchors can't be null, set to undefined
  * No need to call UCUnits::resolveResource to learn we just need to load it
    normally because the fact that we already loaded it normally means we need
    to load it normally. Fixes LP: #1558663.
  * Fix conditional jump or move depends on uninitialised value(s)

  [ Christian Dywan ]
  * Initialize UCApplication with no side effects. Fixes LP: #1662868.
  * Unit test case insensitive FilterBehavior.pattern. Fixes LP: #1663924.
  * ListItemPopover delegate should (in)visible as per action Bug 1662220:
    [ListItem] Popupmenu shows traces of disabled actions

  [ Olivier Tilloy ]
  * Check that window is not null before accessing its activeFocusItem property.
    Fixes LP: #1664620.

  [ Lukáš Tinkl ]
  * Unbreak the startup race between unity8/qtmir and UITK trying talk to
    content-hub. Fixes LP: #1663106.

 -- Zoltán Balogh <email address hidden> Mon, 06 Mar 2017 16:04:56 +0000