Bug 177449 – REGRESSION(r222392): [WPE][GTK] Many forms tests are failing due to broken event timestamps

• Status: RESOLVED
• Resolution: FIXED
• Component: WebKitGTK

[Michael Catanzaro]

r222392 "Use high resolution timestamp for event time" broke the following layout tests for GTK:

  fast/forms/ValidityState-valueMissing-002.html
  fast/forms/listbox-selection-after-typeahead.html
  fast/forms/listbox-typeahead-scroll.html
  fast/forms/onchange-select-check-validity.html
  fast/forms/select-double-onchange.html
  fast/forms/select-script-onchange.html
  fast/forms/select/menulist-oninput-fired.html
  fast/forms/select/select-disabled.html

That's in addition to bug #177444 and bug #177447. Updating expectations accordingly.

The failures all look different and weird:

--- /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/ValidityState-valueMissing-002-expected.txt
+++ /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/ValidityState-valueMissing-002-actual.txt
@@ -15,8 +15,8 @@
 PASS valueMissingFor("select-without-fake-placeholder-size2-multiple") is false
 Updating valueMissing state by a key input:
 PASS valueMissingFor("select-selecting-by-key") is true
-PASS select.value is "a"
-PASS valueMissingFor("select-selecting-by-key") is false
+FAIL select.value should be a. Was .
+FAIL valueMissingFor("select-selecting-by-key") should be false. Was true.
 PASS valueMissingFor("select-selecting-by-key-2") is true
 PASS select.value is "a"
 PASS valueMissingFor("select-selecting-by-key-2") is false


--- /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/listbox-selection-after-typeahead-expected.txt
+++ /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/listbox-selection-after-typeahead-actual.txt
@@ -4,8 +4,8 @@
 
 
 PASS mouseDownAtOption(1);               bitPatternForSelectedOptions() is "0100000"
-PASS sendkeyDown("5");                   bitPatternForSelectedOptions() is "0000010"
-PASS sendkeyDown("upArrow", "shiftKey"); bitPatternForSelectedOptions() is "0000110"
+FAIL sendkeyDown("5");                   bitPatternForSelectedOptions() should be 0000010. Was 0100000.
+FAIL sendkeyDown("upArrow", "shiftKey"); bitPatternForSelectedOptions() should be 0000110. Was 1100000.
 PASS successfullyParsed is true
 
 TEST COMPLETE


--- /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/listbox-typeahead-scroll-expected.txt
+++ /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/listbox-typeahead-scroll-actual.txt
@@ -1,4 +1,4 @@
 Test for http://bugs.webkit.org/show_bug.cgi?id=13013 REGRESSION: Selection box does not scroll to where the focus jumps when pressing an alphanumeric key.
 
 
-SUCCESS
+FAIL


--- /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/onchange-select-check-validity-expected.txt
+++ /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/onchange-select-check-validity-actual.txt
@@ -1,4 +1,4 @@
 
 The select's validity was initially false
-The select's validity was changed to true
+The select's validity was changed to false
 

--- /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/select-double-onchange-expected.txt
+++ /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/select-double-onchange-actual.txt
@@ -1,5 +1,5 @@
 Test for http://bugs.webkit.org/show_bug.cgi?id=13857 REGRESSION: onChange function applied to select element executes twice when focus is set.
 
-SUCCESS
+To test interactively, select the other option in the pop up. This text should change to SUCCESS.
 
 
--- /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/select-script-onchange-expected.txt
+++ /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/select-script-onchange-actual.txt
@@ -1,6 +1,7 @@
 Test for http://bugs.webkit.org/show_bug.cgi?id=23721 Changing dropdown's selectedIndex within onchange handler fires another onchange.
 
-SUCCESS
+
+FAILURE: onchange(2) called 0 times.
 
 This select changes on focus: should not fire onchange.  
 This select changes on change: should only fire onchange once.  


--- /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/select/menulist-oninput-fired-expected.txt
+++ /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/select/menulist-oninput-fired-actual.txt
@@ -2,7 +2,6 @@
 
 
 Pressing 2 key
-PASS
 PASS successfullyParsed is true
 
 TEST COMPLETE


--- /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/select/select-disabled-expected.txt
+++ /home/slave/webkitgtk/gtk-linux-64-release-tests/build/layout-test-results/fast/forms/select/select-disabled-actual.txt
@@ -8,9 +8,9 @@
 PASS select1.value is "b"
 PASS select1.value is "b"
 PASS select2.value is "a"
-PASS select2.value is "b"
-PASS select2.value is "b"
-PASS select2.value is "b"
+FAIL select2.value should be b. Was a.
+FAIL select2.value should be b. Was a.
+FAIL select2.value should be b. Was a.
 PASS successfullyParsed is true
 
 TEST COMPLETE

[Chris Dumez]

I suspect eventSender.keyDown() stopped working for some reason?

[Michael Catanzaro]

*** Bug 177444 has been marked as a duplicate of this bug. ***

[Michael Catanzaro]

Also: fast/events/popup-when-select-change.html

[Chris Dumez]

I wonder if setting the event's time field to GDK_CURRENT_TIME in EventSenderProxy::keyDown() would help (similarly to what is done in EventSenderProxy::createMouseButtonEvent().

[Chris Dumez]

(In reply to Chris Dumez from comment #4)
> I wonder if setting the event's time field to GDK_CURRENT_TIME in
> EventSenderProxy::keyDown() would help (similarly to what is done in
> EventSenderProxy::createMouseButtonEvent().

My bet is that this is caused by GTK's EventSenderProxy failing to set simulated key/mouse event's timestamp in some cases. I need to look into this more but my patch might have changed behavior here because the native event's WallTime now gets converted into a MonotonicTime and I do not know what it does when the WallTime is 0.

[Chris Dumez]

Created attachment 321731 [details]
Proposed patch

Would you mind testing this?

[Chris Dumez]

Comment on attachment 321731 [details]
Proposed patch

View in context: https://bugs.webkit.org/attachment.cgi?id=321731&action=review

> Source/WTF/wtf/WallTime.cpp:43
> +    if (!m_value)

I talked to Phil and we probably would not want to land this. I would still like to know if it fixes the issue for the GTK port to help me understand.
Chances are the right fix will be to properly set the event's time in EventSenderProxy (assuming this fixes the issue).

[Chris Dumez]

Created attachment 321736 [details]
GTK-specific fix

Proposed GTK-specific fix. Please feel free to land this one if it works (I cannot test myself).

[Michael Catanzaro]

Unfortunately I think that patch is a no-op because GDK_CURRENT_TIME is an alias for 0 (actually 0L) and gdk_event_new() ensures the struct is initially zeroed.

[Chris Dumez]

Ok, I think that the simulated PlatformEvents from GTK may be 0 as timestamp (WallTime). When it gets converted to a MonotonicTime, we may end with a negative value when calling WallTime::approximateMonotonicTime().

If we get a negative MonotonicTime value, the following check in TypeAhead::handleEvent() will always be true:
    if (event->timeStamp() < m_lastTypeTime)
        return -1;

.. because m_lastTypeTime is 0.

[Chris Dumez]

(In reply to Chris Dumez from comment #10)
> Ok, I think that the simulated PlatformEvents from GTK may be 0 as timestamp
> (WallTime). When it gets converted to a MonotonicTime, we may end with a
> negative value when calling WallTime::approximateMonotonicTime().
> 
> If we get a negative MonotonicTime value, the following check in
> TypeAhead::handleEvent() will always be true:
>     if (event->timeStamp() < m_lastTypeTime)
>         return -1;
> 
> .. because m_lastTypeTime is 0.

I will propose a fix making the code more robust against having PlatformEvent::timestamp() returning 0. However, if this is really the problem, I think the GTK port should make sure to to initialize it with WallTime::now() when it is 0.

I think this may be observable by firing an event using eventSender.keyDown() then checking event.timeStamp in JS.

[Chris Dumez]

Created attachment 321746 [details]
Proposed change

Could someone please let me know if this fixes the issue for GTK?

[Build Bot]

Attachment 321746 [details] did not pass style-queue:


ERROR: Source/WebCore/platform/PlatformEvent.h:29:  Alphabetical sorting problem.  [build/include_order] [4]
Total errors found: 1 in 5 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Michael Catanzaro]

(In reply to Chris Dumez from comment #12)
> Created attachment 321746 [details]
> Proposed change
> 
> Could someone please let me know if this fixes the issue for GTK?

Confirmed fixed. Nice, thank you!

Will you handle landing it?

Note that I added failure expectations for these tests in r222461.

[Chris Dumez]

(In reply to Michael Catanzaro from comment #14)
> (In reply to Chris Dumez from comment #12)
> > Created attachment 321746 [details]
> > Proposed change
> > 
> > Could someone please let me know if this fixes the issue for GTK?
> 
> Confirmed fixed. Nice, thank you!
> 
> Will you handle landing it?
> 
> Note that I added failure expectations for these tests in r222461.

I can land it tomorrow but if you’re in a hurry, feel free to land earlier.

[Michael Catanzaro]

No hurry. Thanks.

(In reply to Chris Dumez from comment #11)
> I will propose a fix making the code more robust against having
> PlatformEvent::timestamp() returning 0. However, if this is really the
> problem, I think the GTK port should make sure to to initialize it with
> WallTime::now() when it is 0.

I did a bit of digging. It looks like this already occurs for PlatformKeyboardEvent and PlatformWheelEvent in the constructors for those events (in PlatformKeyboardEventGtk.cpp and PlatformWheelEventGtk.cpp). So not sure what has gone wrong there.

PlatformMouseEvent's GTK constructor takes the time instead from the underlying GdkEventMotion using WallTime::fromRawSeconds, which looks wrong because it's passing *milliseconds* into that function. But it looks like these broken tests involved keyboard events, not mouse events.

[Chris Dumez]

(In reply to Michael Catanzaro from comment #16)
> No hurry. Thanks.
> 
> (In reply to Chris Dumez from comment #11)
> > I will propose a fix making the code more robust against having
> > PlatformEvent::timestamp() returning 0. However, if this is really the
> > problem, I think the GTK port should make sure to to initialize it with
> > WallTime::now() when it is 0.
> 
> I did a bit of digging. It looks like this already occurs for
> PlatformKeyboardEvent and PlatformWheelEvent in the constructors for those
> events (in PlatformKeyboardEventGtk.cpp and PlatformWheelEventGtk.cpp). So
> not sure what has gone wrong there.
> 
> PlatformMouseEvent's GTK constructor takes the time instead from the
> underlying GdkEventMotion using WallTime::fromRawSeconds, which looks wrong
> because it's passing *milliseconds* into that function. But it looks like
> these broken tests involved keyboard events, not mouse events.

I believe the issue could be in WebEventFactory::createWebKeyboardEvent(). The GTK version does:
WallTime::fromRawSeconds(gdk_event_get_time(event))

I guess gdk_event_get_time(event) may return 0, which for GTK means current time.

[Chris Dumez]

Created attachment 321823 [details]
Patch

[Build Bot]

Attachment 321823 [details] did not pass style-queue:


ERROR: Source/WebKit/Shared/gtk/WebEventFactory.cpp:151:  Weird number of spaces at line-start.  Are you using a 4-space indent?  [whitespace/indent] [3]
Total errors found: 1 in 7 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Chris Dumez]

Created attachment 321825 [details]
Patch

[Chris Dumez]

What about wpe_input_keyboard_event's time. Is it in seconds or milliseconds? Is there a special value meaning CURRENT_TIME? My patch only fixes GTK for now, not WPE.

[Build Bot]

Attachment 321825 [details] did not pass style-queue:


ERROR: Source/WebKit/Shared/gtk/WebEventFactory.cpp:151:  Weird number of spaces at line-start.  Are you using a 4-space indent?  [whitespace/indent] [3]
Total errors found: 1 in 7 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Michael Catanzaro]

Thanks a bunch for taking a stab at this, Chris. It's a big help.

(In reply to Chris Dumez from comment #21)
> What about wpe_input_keyboard_event's time. Is it in seconds or
> milliseconds? Is there a special value meaning CURRENT_TIME? My patch only
> fixes GTK for now, not WPE.

I bet we didn't notice that WPE was broken simply because WPE only runs a small subset of the layout tests. I will ask around to get an answer for WPE.

For GTK, I fear that the event timestamp is just some monotonic millisecond timestamp that does not have any relation to real-world time (it's not time since the epoch), so passing it into WallTime will never be right. This is going to need a total rethink. We'll take care of it.

[Chris Dumez]

(In reply to Michael Catanzaro from comment #23)
> Thanks a bunch for taking a stab at this, Chris. It's a big help.
> 
> (In reply to Chris Dumez from comment #21)
> > What about wpe_input_keyboard_event's time. Is it in seconds or
> > milliseconds? Is there a special value meaning CURRENT_TIME? My patch only
> > fixes GTK for now, not WPE.
> 
> I bet we didn't notice that WPE was broken simply because WPE only runs a
> small subset of the layout tests. I will ask around to get an answer for WPE.
> 
> For GTK, I fear that the event timestamp is just some monotonic millisecond
> timestamp that does not have any relation to real-world time (it's not time
> since the epoch), so passing it into WallTime will never be right. This is
> going to need a total rethink. We'll take care of it.

Ok, some more work will be needed to be completely correct if event->time is not a number of ms since Epoch.

What's causing the tests failing though seems to be not dealing with GDK_CURRENT_TIME and converting it to WallTime::now() which my patch takes care of.

Note that NSEvents on Mac/iOS also do not use a number of seconds since Epoch but rather a number of seconds since the computer booted. Our code deals with this because constructing WebKit's event types.

[Michael Catanzaro]

Comment on attachment 321825 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=321825&action=review

> Source/WebKit/Shared/gtk/WebEventFactory.cpp:49
> +static inline WallTime eventTime(const GdkEvent* event)

We'll also want to move this to some shared location (maybe PlatformEvent) to avoid the code duplication.

> Source/WebKit/Shared/gtk/WebEventFactory.cpp:54
> +    return WallTime::fromRawSeconds(timeInMilliseconds / 1000.);

And then here we could add a FIXME to figure out how to convert properly from the event timestamp to wall time. It's probably not possible. We might need to just always set the event timestamps to WallTime::now(). I'll wait and see if any of our other developers have a suggestion.

[Chris Dumez]

Yes, maybe you'd want to use WallTime::now() consistently until the event's timestamps can properly be converted. Seems the event's timestamps was already being ignored in a lot of cases.

[Michael Catanzaro]

Still looking into the best approach to this problem. Turns out the timestamps *can* be converted under certain conditions.

[Michael Catanzaro]

Created attachment 322399 [details]
Patch

[Chris Dumez]

Comment on attachment 322399 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=322399&action=review

> Source/WebCore/platform/gtk/GtkUtilities.h:32
> +WallTime wallTimeForEvent(const GdkEvent*);

To avoid having to reinterpret_cast at call sites, it seems like we could use templating no?:
WallTime wallTimeForEvent(const GdkEvent*);
template<typename GdkEventType> WallTime wallTimeForEvent(const GdkEventType* event) { return MonotonicTime::fromRawSeconds(event->time / 1000.).approximateWallTime(); }

// in cpp.
WallTime wallTimeForEvent(const GdkEvent* event)
{
    // This works if and only if the X server or Wayland compositor happens to
    // be using CLOCK_MONOTONIC for its monotonic time, and so long as
    // g_get_monotonic_time() continues to do so as well, and so long as
    // WTF::MonotonicTime continues to use g_get_monotonic_time().
    return MonotonicTime::fromRawSeconds(gdk_event_get_time(event) / 1000.).approximateWallTime();
}

[Michael Catanzaro]

Good point, that would indeed be nicer.

[Michael Catanzaro]

Created attachment 322413 [details]
Patch

[Chris Dumez]

Comment on attachment 322413 [details]
Patch

r=me

[WebKit Commit Bot]

Comment on attachment 322413 [details]
Patch

Clearing flags on attachment: 322413

Committed r222776: <http://trac.webkit.org/changeset/222776>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Michael Catanzaro]

This patch was correct and should not be reverted, but it didn't fix the tests like your second patch did. We might need that too. I'm starting a build that will allow me to run layout tests locally to see what's going on in those tests.

[Chris Dumez]

Comment on attachment 322399 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=322399&action=review

> Source/WebCore/platform/gtk/GtkUtilities.cpp:65
> +    return MonotonicTime::fromRawSeconds(gdk_event_get_time(event) / 1000.).approximateWallTime();

You probably need to deal with the time stamp being 0 here and use WallTime::now() then.

[Michael Catanzaro]

I'll try that. And prepare for another sad rebuild. Stupid header files....

Anyway, the tests all pass if I revert my patch and use yours instead, but they still fail when I apply your patch on top of mine.

[Michael Catanzaro]

Created attachment 322534 [details]
Patch

[Michael Catanzaro]

You were right. This is tested on the layout tests and actually works. :)

I tried to skip that responsibility this morning due to an unusual build setup that made building WebKit in a manner suitable for running layout tests a bit difficult....

[Chris Dumez]

Comment on attachment 322534 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=322534&action=review

> Source/WebCore/platform/gtk/GtkUtilities.cpp:64
> +    auto time = gdk_event_get_time(event) / 1000.;

I think this would read better as:

auto gdkEventTime = gdk_event_get_time(event);
if (gdkEventTime == GDK_CURRENT_TIME)
    return WallTime::now();
return MonotonicTime::fromRawSeconds(gdkEventTime).approximateWallTime();

but it is your call.

> Source/WebCore/platform/gtk/GtkUtilities.h:37
> +    return time ? MonotonicTime::fromRawSeconds(time).approximateWallTime() : WallTime::now();

ditto.

> Source/WebKit/Shared/wpe/WebEventFactory.cpp:83
> +    return seconds ? MonotonicTime::fromRawSeconds(seconds).approximateWallTime() : WallTime::now();

ditto.

[Chris Dumez]

Comment on attachment 322534 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=322534&action=review

>> Source/WebCore/platform/gtk/GtkUtilities.cpp:64
>> +    auto time = gdk_event_get_time(event) / 1000.;
> 
> I think this would read better as:
> 
> auto gdkEventTime = gdk_event_get_time(event);
> if (gdkEventTime == GDK_CURRENT_TIME)
>     return WallTime::now();
> return MonotonicTime::fromRawSeconds(gdkEventTime).approximateWallTime();
> 
> but it is your call.

sorry, should have been:

auto gdkEventTime = gdk_event_get_time(event);
if (gdkEventTime == GDK_CURRENT_TIME)
    return WallTime::now();
return MonotonicTime::fromRawSeconds(gdkEventTime / 1000.).approximateWallTime();

[Michael Catanzaro]

(In reply to Chris Dumez from comment #41) 
> auto gdkEventTime = gdk_event_get_time(event);
> if (gdkEventTime == GDK_CURRENT_TIME)
>     return WallTime::now();
> return MonotonicTime::fromRawSeconds(gdkEventTime /
> 1000.).approximateWallTime();

Ah yes, much better! Thanks Chris!

[Michael Catanzaro]

Created attachment 322639 [details]
Patch for landing

[WebKit Commit Bot]

Comment on attachment 322639 [details]
Patch for landing

Clearing flags on attachment: 322639

Committed r222837: <http://trac.webkit.org/changeset/222837>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Michael Catanzaro]

Reopening to attach new patch.

[Michael Catanzaro]

Created attachment 322662 [details]
Patch for landing

[WebKit Commit Bot]

Comment on attachment 322662 [details]
Patch for landing

Clearing flags on attachment: 322662

Committed r222846: <http://trac.webkit.org/changeset/222846>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.