UbuntuTestCase's flick() function is unreliable, does not always flick a Flickable

[Andrea Bernabei]

revision 1864

System setup: Vivid + Overlay PPA (i.e. same as phones/tablets)

libqt5qml5:
  Installed: 5.4.1-1ubuntu11~overlay3
libqt5core5a:
  Installed: 5.4.1+dfsg-2ubuntu11~vivid4

UbuntuTestCase provides a flick() function whose main purpose is to produce a flick event when executed on Flickable.

I noticed that this does not always happen, causing flakiness of some of the UITK tests (in my case, it's the Scrollbar/ScrollView tests I'm working on)

Here is a test case that reproduces the issue, once every 10-200 runs, depending on the configuration (I use a simple script to run it until it fails)

Please note that uncommenting the debug lines such as onMovingChanged onFlickingChanged will make it harder to reproduce the bug.

Enabling QT_LOGGING_RULES="qt.quick.mouse.debug=true" or onContentYChanged will make it even harder.

Since I already went through the effort, I'm posting here the debug log coming from the failed and successful runs:
- Typical failed run ---> http://pastebin.ubuntu.com/15186789/ Note how "flicking" never becomes true
- Typical successful run ---> http://pastebin.ubuntu.com/15186784/

- Failed test with qt.quick.mouse.debug=true --> http://pastebin.ubuntu.com/15186851/
- Successful test with qt.quick.mouse.debug=true -> http://pastebin.ubuntu.com/15186853/

Here's the code I used to reproduce the bug:

import QtQuick 2.4
import QtTest 1.0
import Ubuntu.Test 1.0
import Ubuntu.Components 1.3
import Ubuntu.Components.Styles 1.3
import QtQml.Models 2.1

Item {
    id: main
    width: units.gu(50)
    height: units.gu(100)

    SignalSpy {
        id: signalSpy
    }
    SignalSpy {
        id: anotherSignalSpy
    }

    Item {
        anchors.fill: parent
        Item {
            width: units.gu(20)
            height: units.gu(30)
            property alias flickable: freshFlickable
            Flickable {
                id: freshFlickable
                anchors.fill: parent
                contentHeight: content.height
                contentWidth: content.width
                clip: true
                //onContentYChanged: console.log(contentY)
                //onMovingChanged: console.log("MOVING", moving)
                //onFlickingChanged: console.log("FLICKING", flicking)
                Rectangle {
                    id: content
                    width: units.gu(40)
                    height: units.gu(200)
                    color: "blue"
                }
            }
        }
    }

    UbuntuTestCase {
        name: "FlickBug"
        when: windowShown

        function setupSignalSpy(spy, target, signalName) {
            spy.clear()
            //reset signalName otherwise it will look for the old signalName in the new target
            spy.signalName = ""
            spy.target = target
            spy.signalName = signalName
        }

        function test_flickUbuntuTestCase() {
            setupSignalSpy(signalSpy, freshFlickable, "movingChanged")
            flick(freshFlickable, 50, 50, -units.gu(10), -units.gu(10))
            signalSpy.wait()
            compare(signalSpy.count, 1, "No movingChanged signal after simulating a flick.")
        }
    }
}

[Andrea Bernabei (faenil)]

I investigated the issue by recompiling the QtQuick module and adding some debug info in qquickflickable.cpp

I added some debug in void QQuickFlickablePrivate::handleMouseMoveEvent(QMouseEvent *event)
(I only added qDebug, the extra lines are to show the context)

    if ((hMoved && !prevHMoved) || (vMoved && !prevVMoved))
        q->movementStarting();

    qint64 currentTimestamp = computeCurrentTime(event);
    qreal elapsed = qreal(currentTimestamp - (lastPos.isNull() ? lastPressTime : lastPosTime)) / 1000.;
    qDebug() << QString("Elapsed " % QString::number(elapsed) % " currentTimestamp " % QString::number(currentTimestamp)
             % " lastPos.isNull " % QString::number(lastPos.isNull()) % " lastPressTime " % QString::number(lastPressTime)
             % " lastPosTime " % QString::number(lastPosTime) % " vertical velocity " % QString::number(vData.velocity)
             % " horizontal velocity " % QString::number(hData.velocity));
    if (elapsed <= 0)
        return;

And I added some debug in the handleMouseReleaseEvent as well

    qDebug() << QString("Mouse release! Elapsed " % QString::number(elapsed) % " vertical velocity " % QString::number(vData.velocity)
                % " horizontal velocity " % QString::number(hData.velocity));
    qreal vVelocity = 0;
    if (elapsed < 100 && vData.velocity != 0.) {
        vVelocity = (QGuiApplicationPrivate::mouseEventCaps(event) & QTouchDevice::Velocity)
                ? QGuiApplicationPrivate::mouseEventVelocity(event).y() : vData.velocity;
    }

The resulting log is at http://pastebin.ubuntu.com/15196346/

[Andrea Bernabei (faenil)]

So, what the log I previously posted shows, is that it occasionally happens that all events are delivered with 0 time difference between them.
As a consequence, the vertical and horizontal velocity of the Flickable never change from 0, and that causes the flick not to start, when the mouse/tap is released.

[Andrea Bernabei (faenil)]

Some more info:

After adding a debug line for "event->timestamp()" as well, it turns out on my machine (this is most likely not only happening on my machine though) the timestamps for mouse events are always 0 (probably just not supported by the middleware or something similar). See this log for both a successful and failing run, the events timestamps are always 0 http://pastebin.ubuntu.com/15196543/

When timestamps are 0, QQuickFlickable uses a QElapsedTimer to check how many msecs passed since the press event.
Proof: https://github.com/qtproject/qtdeclarative/blob/5.4/src/quick/items/qquickflickable.cpp#L916

On my machine (just like it should be on any other Linux platform) QElapsedTimer is using the monotonic clock (checked with another debug line in qquickflickable.cpp).

So, what happens, is probably that the Press -> move -> move -> move -> move -> Release events generated by the flick() function are some times all delivered in the same batch.

In that case, QElapsedTimer::elapsed() always returns 0, and that causes the event to be ignored by the velocity computation logic.
Proof:
https://github.com/qtproject/qtdeclarative/blob/5.4/src/quick/items/qquickflickable.cpp#L1096

As a consequence, when the mouse release happens, the flick is not started because velocity is believed to be 0.

[Launchpad Janitor (janitor)]

This bug was fixed in the package ubuntu-ui-toolkit - 1.3.1872+16.04.20160308-0ubuntu1

---------------
ubuntu-ui-toolkit (1.3.1872+16.04.20160308-0ubuntu1) xenial; urgency=medium

  [ Timo Jyrinki ]
  * Fix gles unit test skipping.
  * Add s390x to the unit test skipping architectures
  * UITK test plan - wily -> xenial. Fixes LP: #1544490

  [ Christian Dywan ]
  * Print errors when QuickUtils fails to create a component.
  * unit tests shouldn't use deprecated Dialog.callera
  * Correctly count only test case results. The result= value is used in suites
    and results.
  * Skip tst_pagehead_visible flakes on non-arm. Fixes LP: #1534651
  * Skip flaky tst_mousefilterTest::doubleClicked. Fixes LP: #1542215
  * Suppress click signal if releasing outside of ListItem. Fixes LP: #1541148.
  * Use gdb in runtest.sh to produce backtraces.
  * Arrow keys change value of a Slider. Fixes LP: #1523824.
  * Only use Maliit when enabled explicitly in the environment

  [ Oliver Tilloy ]
  * Do not try to assign to non-existent property "activeFocusOnPress".
    Fixes LP: #1532953
  * Bubble up ESC key press event if there is no popover to close.
    Fixes LP: #1546627

  [ Loïc Molinari ]
  * Added private items and nodes for the new component styles.
    Fixes LP: #1523836
  * Made use of new private Frame item for the focusing.
  * Fixed performance monitor crash because of a NULL timer pointer dereference.
    Fixes LP: #1546986
  * Fixed performance monitor dangling pointer crash. Fixes LP: #1546984
  * [ProportionalShape] Ensured width/height ratio is correct with default values.
    Fixes LP: #1546546
  * Added a workaround to prevent a crash while changing the QPA scale factor.

  [ Florian Boucault ]
  * Always on performance monitor that logs frames that too long to render.
  * MainView: proceed to selecting the theme automatically at startup too.
    Fixes LP: #1535819
  * MainView: when no gradient color is needed for the background, rely on
    QQuickWindow's GL clear color. Lessens overdraw considerably for most
    apps. Fixes LP: #1439133.
  * Panel: MathUtils used without import prefix was leading to undefined
    reference.
  * Label: use native rendering on low dpi screens (GRID_UNIT_PX <= 10) for
    sharper looking text.
  * Gallery: added palette browser to Colors page.

  [ Tim Peeters ]
  * Support scrolling in ListViews with horizontal orientation to the
    qquicklistview CPO.
  * Add background to AppHeader and remove contents clipping from MainView.
    Fixes LP: #1531016, LP: #1531457.
  * Hide AppHeader when using AdaptivePageLayout. Fixes bug 1531871.
    Fixes LP: #1531871.
  * Implement horizontal flicking in the flickable autopilot CPO.
  * Re-order to list of pages in the gallery to be alphabetical.
  * Fix the autopilot failures introduced with the horizontal scrolling in
    the Flickable CPO.
  * Update documentation for MainView, Page, AdaptivePageLayout to use the new
    PageHeader in all examples. Deprecate old properties. Fixes LP: #1540574
  * Add 'animate' property to new internal AppHeaderBase, and do not show a
    header animation when starting an app without header.
    Fixes LP: #1518002, LP: #1524901.
 ...