QML: emit messages when breaking bindings

Add a new logging category that can be used to debug issues with
unexpected binding breakages caused by assignment to previously bound
properties. If enabled, outputs a message when a binding is broken with
detailed location and property/value information.

[ChangeLog][QtQml] The QML engine can now emit informational messages
(in the "qt.qml.binding.removal" logging category) whenever a binding is
lost due to an imperative assignment. This can be used to debug issues
due to broken bindings.

Change-Id: Ie31e5a198450b6f998c1266acfc97e8f33a92e3d
Reviewed-by: Simon Hausmann <simon.hausmann@qt.io>

5 files changed, 89 insertions, 6 deletions

diff --git a/src/qml/doc/src/qmllanguageref/syntax/propertybinding.qdoc b/src/qml/doc/src/qmllanguageref/syntax/propertybinding.qdoc
index f28ff5082a..99426d984d 100644
--- a/src/qml/doc/src/qmllanguageref/syntax/propertybinding.qdoc
+++ b/src/qml/doc/src/qmllanguageref/syntax/propertybinding.qdoc
@@ -179,6 +179,26 @@ Rectangle {
 Now, after the space key is pressed, the rectangle's height will continue
 auto-updating to always be three times its width.
 
+\section3 Debugging overwriting of bindings
+
+A common cause of bugs in QML applications is accidentally overwriting bindings
+with static values from JavaScript statements. To help developers track down
+problems of this kind, the QML engine is able to emit messages whenever a
+binding is lost due to imperative assignments.
+
+In order to generate such messages, you need to enable the informational output
+for the \c{qt.qml.binding.removal} logging category, for instance by calling:
+
+\code
+QLoggingCategory::setFilterRules(QStringLiteral("qt.qml.binding.removal.info=true"));
+\endcode
+
+Please refer to the QLoggingCategory documentation for more information about
+enabling output from logging categories.
+
+Note that is perfectly reasonable in some circumstances to overwrite bindings.
+Any message generated by the QML engine should be treated as a diagnostic aid,
+and not necessarily as evidence of a problem without further investigation.
 
 \section2 Using \c this with Property Binding
 
diff --git a/src/qml/jsruntime/qv4qobjectwrapper.cpp b/src/qml/jsruntime/qv4qobjectwrapper.cpp
index e4fb54f0ff..83730d632a 100644
--- a/src/qml/jsruntime/qv4qobjectwrapper.cpp
+++ b/src/qml/jsruntime/qv4qobjectwrapper.cpp
@@ -75,10 +75,13 @@
 #include <QtCore/qatomic.h>
 #include <QtCore/qmetaobject.h>
 #include <QtCore/qabstractitemmodel.h>
+#include <QtCore/qloggingcategory.h>
 
 #include <vector>
 QT_BEGIN_NAMESPACE
 
+Q_LOGGING_CATEGORY(lcBindingRemoval, "qt.qml.binding.removal", QtWarningMsg)
+
 // The code in this file does not violate strict aliasing, but GCC thinks it does
 // so turn off the warnings for us to have a clean build
 QT_WARNING_DISABLE_GCC("-Wstrict-aliasing")
@@ -458,10 +461,23 @@ void QObjectWrapper::setProperty(ExecutionEngine *engine, QObject *object, QQmlP
         }
     }
 
-    if (newBinding)
+    if (newBinding) {
         QQmlPropertyPrivate::setBinding(newBinding);
-    else
+    } else {
+        if (Q_UNLIKELY(lcBindingRemoval().isInfoEnabled())) {
+            if (auto binding = QQmlPropertyPrivate::binding(object, QQmlPropertyIndex(property->coreIndex()))) {
+                Q_ASSERT(!binding->isValueTypeProxy());
+                const auto qmlBinding = static_cast<const QQmlBinding*>(binding);
+                const auto stackFrame = engine->currentStackFrame();
+                qCInfo(lcBindingRemoval,
+                       "Overwriting binding on %s::%s at %s:%d that was initially bound at %s",
+                       object->metaObject()->className(), qPrintable(property->name(object)),
+                       qPrintable(stackFrame.source), stackFrame.line,
+                       qPrintable(qmlBinding->expressionIdentifier()));
+            }
+        }
         QQmlPropertyPrivate::removeBinding(object, QQmlPropertyIndex(property->coreIndex()));
+    }
 
     if (!newBinding && property->isVarProperty()) {
         // allow assignment of "special" values (null, undefined, function) to var properties
diff --git a/src/qml/qml/qqmlvaluetypewrapper.cpp b/src/qml/qml/qqmlvaluetypewrapper.cpp
index d262b230e2..ce47ab9fa9 100644
--- a/src/qml/qml/qqmlvaluetypewrapper.cpp
+++ b/src/qml/qml/qqmlvaluetypewrapper.cpp
@@ -51,9 +51,11 @@
 #include <private/qv4alloca_p.h>
 #include <private/qv4objectiterator_p.h>
 #include <private/qv4qobjectwrapper_p.h>
+#include <QtCore/qloggingcategory.h>
 
 QT_BEGIN_NAMESPACE
 
+Q_DECLARE_LOGGING_CATEGORY(lcBindingRemoval)
 
 DEFINE_OBJECT_VTABLE(QV4::QQmlValueTypeWrapper);
 
@@ -438,6 +440,9 @@ bool QQmlValueTypeWrapper::put(Managed *m, String *name, const Value &value)
 
     if (reference) {
         QV4::ScopedFunctionObject f(scope, value);
+        const QQmlQPointer<QObject> &referenceObject = reference->d()->object;
+        const int referencePropertyIndex = reference->d()->property;
+
         if (f) {
             if (!f->isBinding()) {
                 // assigning a JS function to a non-var-property is not allowed.
@@ -452,18 +457,31 @@ bool QQmlValueTypeWrapper::put(Managed *m, String *name, const Value &value)
             QQmlPropertyData cacheData;
             cacheData.setWritable(true);
             cacheData.setPropType(writeBackPropertyType);
-            cacheData.setCoreIndex(reference->d()->property);
+            cacheData.setCoreIndex(referencePropertyIndex);
 
             QV4::Scoped<QQmlBindingFunction> bindingFunction(scope, (const Value &)f);
 
             QV4::ScopedContext ctx(scope, bindingFunction->scope());
-            QQmlBinding *newBinding = QQmlBinding::create(&cacheData, bindingFunction->function(), reference->d()->object, context, ctx);
+            QQmlBinding *newBinding = QQmlBinding::create(&cacheData, bindingFunction->function(), referenceObject, context, ctx);
             newBinding->setSourceLocation(bindingFunction->currentLocation());
-            newBinding->setTarget(reference->d()->object, cacheData, pd);
+            newBinding->setTarget(referenceObject, cacheData, pd);
             QQmlPropertyPrivate::setBinding(newBinding);
             return true;
         } else {
-            QQmlPropertyPrivate::removeBinding(reference->d()->object, QQmlPropertyIndex(reference->d()->property, pd->coreIndex()));
+            if (Q_UNLIKELY(lcBindingRemoval().isInfoEnabled())) {
+                if (auto binding = QQmlPropertyPrivate::binding(referenceObject, QQmlPropertyIndex(referencePropertyIndex, pd->coreIndex()))) {
+                    Q_ASSERT(!binding->isValueTypeProxy());
+                    const auto qmlBinding = static_cast<const QQmlBinding*>(binding);
+                    const auto stackFrame = v4->currentStackFrame();
+                    qCInfo(lcBindingRemoval,
+                           "Overwriting binding on %s::%s which was initially bound at %s by setting \"%s\" at %s:%d",
+                           referenceObject->metaObject()->className(), referenceObject->metaObject()->property(referencePropertyIndex).name(),
+                           qPrintable(qmlBinding->expressionIdentifier()),
+                           metaObject->property(pd->coreIndex()).name(),
+                           qPrintable(stackFrame.source), stackFrame.line);
+                }
+            }
+            QQmlPropertyPrivate::removeBinding(referenceObject, QQmlPropertyIndex(referencePropertyIndex, pd->coreIndex()));
         }
     }
 
diff --git a/tests/auto/qml/qqmlbinding/data/bindingOverwriting.qml b/tests/auto/qml/qqmlbinding/data/bindingOverwriting.qml
new file mode 100644
index 0000000000..767ca0c719
--- /dev/null
+++ b/tests/auto/qml/qqmlbinding/data/bindingOverwriting.qml
@@ -0,0 +1,13 @@
+import QtQuick 2.9
+
+Text {
+    visible: text && enabled
+    enabled: font.pixelSize === 25
+    font: enabled ? Qt.font({ "pixelSize": 25 }) : Qt.font({ "pixelSize": 50 })
+
+    Component.onCompleted: {
+        enabled = Qt.binding(function() { return visible; }); // replacement binding, not breaking
+        visible = true; // breaks visible binding
+        font.bold = true; // breaks font binding
+    }
+}
diff --git a/tests/auto/qml/qqmlbinding/tst_qqmlbinding.cpp b/tests/auto/qml/qqmlbinding/tst_qqmlbinding.cpp
index 6f1d82eca5..4b485d2ce8 100644
--- a/tests/auto/qml/qqmlbinding/tst_qqmlbinding.cpp
+++ b/tests/auto/qml/qqmlbinding/tst_qqmlbinding.cpp
@@ -50,6 +50,7 @@ private slots:
     void disabledOnUnknownProperty();
     void disabledOnReadonlyProperty();
     void delayed();
+    void bindingOverwriting();
 
 private:
     QQmlEngine engine;
@@ -303,6 +304,21 @@ void tst_qqmlbinding::delayed()
     delete item;
 }
 
+void tst_qqmlbinding::bindingOverwriting()
+{
+    QQmlTestMessageHandler messageHandler;
+    QLoggingCategory::setFilterRules(QStringLiteral("qt.qml.binding.removal.info=true"));
+
+    QQmlEngine engine;
+    QQmlComponent c(&engine, testFileUrl("bindingOverwriting.qml"));
+    QQuickItem *item = qobject_cast<QQuickItem*>(c.create());
+    QVERIFY(item);
+    delete item;
+
+    QLoggingCategory::setFilterRules(QString());
+    QCOMPARE(messageHandler.messages().count(), 2);
+}
+
 QTEST_MAIN(tst_qqmlbinding)
 
 #include "tst_qqmlbinding.moc"