Log Message
[Mac] Web Automation: some keyboard interactions don't generate events, causing event simulation to stall https://bugs.webkit.org/show_bug.cgi?id=190316 <rdar://problem/42833290>
Reviewed by Tim Horton. Some users have reported that Cmd-A for Select All no longer works in safaridriver. Instead, this hangs the session. This happens because the WebAutomationSession class assumes that each call to simulateKeyboardInteraction causes keyboard events to be processed, but in corner cases like Cmd-A, some events that we simulate are swallowed by AppKit and never make it back to WebKit. Because the session never gets the "keyboard events flushed" callback, it assumes the interaction is still ongoing, and never returns, causing a hang. This patch consists of two parts: - Add logging of important state changes and events when simulating user input. - Make code more robust when simulating key actions that generate no events on macOS. This change progresses WPT test key_shortcuts.py::test_mod_a_and_backspace_deletes_all_text on Mac. * Platform/Logging.h: Add a logging channel. * UIProcess/Automation/SimulatedInputDispatcher.cpp: (WebKit::SimulatedInputDispatcher::keyFrameTransitionDurationTimerFired): (WebKit::SimulatedInputDispatcher::transitionBetweenKeyFrames): (WebKit::SimulatedInputDispatcher::transitionInputSourceToState): (WebKit::SimulatedInputDispatcher::run): (WebKit::SimulatedInputDispatcher::finishDispatching): Add a bunch of logging so its easier to figure out where things get stuck. * UIProcess/Automation/WebAutomationSession.cpp: (WebKit::WebAutomationSession::simulateKeyboardInteraction): In some cases, no keyboard events need to be processed for the simulated interaction. When that happens, early exit rather than waiting for keyboard events to be flushed. * UIProcess/Automation/mac/WebAutomationSessionMac.mm: (WebKit::WebAutomationSession::sendSynthesizedEventsToPage): Logging. (WebKit::WebAutomationSession::platformSimulateKeyboardInteraction): On Mac, if you tap a character key while Command is held down, only a KeyDown event is forwarded to the first responder by AppKit, even if you send a KeyUp event too. In this case don't send an NSEvent since it won't ever be delivered back to WebKit. * UIProcess/WebPageProxy.h: * UIProcess/WebPageProxy.cpp: (WebKit::WebPageProxy::isProcessingKeyboardEvents const): Expose this state for keyboard events too.
Modified Paths
- trunk/Source/WebKit/ChangeLog
- trunk/Source/WebKit/Platform/Logging.h
- trunk/Source/WebKit/UIProcess/Automation/SimulatedInputDispatcher.cpp
- trunk/Source/WebKit/UIProcess/Automation/WebAutomationSession.cpp
- trunk/Source/WebKit/UIProcess/Automation/mac/WebAutomationSessionMac.mm
- trunk/Source/WebKit/UIProcess/WebPageProxy.cpp
- trunk/Source/WebKit/UIProcess/WebPageProxy.h
Diff
Modified: trunk/Source/WebKit/ChangeLog (236938 => 236939)
--- trunk/Source/WebKit/ChangeLog 2018-10-08 20:37:26 UTC (rev 236938)
+++ trunk/Source/WebKit/ChangeLog 2018-10-08 21:02:20 UTC (rev 236939)
@@ -1,3 +1,50 @@
+2018-10-08 Brian Burg <bb...@apple.com>
+
+ [Mac] Web Automation: some keyboard interactions don't generate events, causing event simulation to stall
+ https://bugs.webkit.org/show_bug.cgi?id=190316
+ <rdar://problem/42833290>
+
+ Reviewed by Tim Horton.
+
+ Some users have reported that Cmd-A for Select All no longer works in safaridriver.
+ Instead, this hangs the session. This happens because the WebAutomationSession class
+ assumes that each call to simulateKeyboardInteraction causes keyboard events to be processed,
+ but in corner cases like Cmd-A, some events that we simulate are swallowed by AppKit and
+ never make it back to WebKit. Because the session never gets the "keyboard events flushed"
+ callback, it assumes the interaction is still ongoing, and never returns, causing a hang.
+
+ This patch consists of two parts:
+ - Add logging of important state changes and events when simulating user input.
+ - Make code more robust when simulating key actions that generate no events on macOS.
+
+ This change progresses WPT test key_shortcuts.py::test_mod_a_and_backspace_deletes_all_text on Mac.
+
+ * Platform/Logging.h: Add a logging channel.
+ * UIProcess/Automation/SimulatedInputDispatcher.cpp:
+ (WebKit::SimulatedInputDispatcher::keyFrameTransitionDurationTimerFired):
+ (WebKit::SimulatedInputDispatcher::transitionBetweenKeyFrames):
+ (WebKit::SimulatedInputDispatcher::transitionInputSourceToState):
+ (WebKit::SimulatedInputDispatcher::run):
+ (WebKit::SimulatedInputDispatcher::finishDispatching):
+ Add a bunch of logging so its easier to figure out where things get stuck.
+
+ * UIProcess/Automation/WebAutomationSession.cpp:
+ (WebKit::WebAutomationSession::simulateKeyboardInteraction):
+ In some cases, no keyboard events need to be processed for the simulated interaction.
+ When that happens, early exit rather than waiting for keyboard events to be flushed.
+
+ * UIProcess/Automation/mac/WebAutomationSessionMac.mm:
+ (WebKit::WebAutomationSession::sendSynthesizedEventsToPage): Logging.
+ (WebKit::WebAutomationSession::platformSimulateKeyboardInteraction):
+ On Mac, if you tap a character key while Command is held down, only a KeyDown event
+ is forwarded to the first responder by AppKit, even if you send a KeyUp event too.
+ In this case don't send an NSEvent since it won't ever be delivered back to WebKit.
+
+ * UIProcess/WebPageProxy.h:
+ * UIProcess/WebPageProxy.cpp:
+ (WebKit::WebPageProxy::isProcessingKeyboardEvents const): Expose this state for keyboard
+ events too.
+
2018-10-08 Youenn Fablet <you...@apple.com>
NetworkCache::Storage should be WTF::DestructionThread::Main
Modified: trunk/Source/WebKit/Platform/Logging.h (236938 => 236939)
--- trunk/Source/WebKit/Platform/Logging.h 2018-10-08 20:37:26 UTC (rev 236938)
+++ trunk/Source/WebKit/Platform/Logging.h 2018-10-08 21:02:20 UTC (rev 236939)
@@ -40,6 +40,7 @@
#endif
#define WEBKIT2_LOG_CHANNELS(M) \
+ M(Automation) \
M(ActivityState) \
M(BackForward) \
M(CacheStorage) \
Modified: trunk/Source/WebKit/UIProcess/Automation/SimulatedInputDispatcher.cpp (236938 => 236939)
--- trunk/Source/WebKit/UIProcess/Automation/SimulatedInputDispatcher.cpp 2018-10-08 20:37:26 UTC (rev 236938)
+++ trunk/Source/WebKit/UIProcess/Automation/SimulatedInputDispatcher.cpp 2018-10-08 21:02:20 UTC (rev 236939)
@@ -27,6 +27,7 @@
#include "SimulatedInputDispatcher.h"
#include "AutomationProtocolObjects.h"
+#include "Logging.h"
#include "WebAutomationSession.h"
#include "WebAutomationSessionMacros.h"
@@ -112,6 +113,8 @@
m_keyFrameTransitionDurationTimer.stop();
+ LOG(Automation, "SimulatedInputDispatcher[%p]: timer finished for transition between keyframes: %d --> %d", this, m_keyframeIndex - 1, m_keyframeIndex);
+
if (isKeyFrameTransitionComplete()) {
auto finish = std::exchange(m_keyFrameTransitionCompletionHandler, nullptr);
finish(std::nullopt);
@@ -187,6 +190,9 @@
m_keyFrameTransitionCompletionHandler = WTFMove(completionHandler);
m_keyFrameTransitionDurationTimer.startOneShot(b.maximumDuration());
+ LOG(Automation, "SimulatedInputDispatcher[%p]: started transition between keyframes: %d --> %d", this, m_keyframeIndex - 1, m_keyframeIndex);
+ LOG(Automation, "SimulatedInputDispatcher[%p]: timer started to ensure minimum duration of %.2f seconds for transition %d --> %d", this, b.maximumDuration().value(), m_keyframeIndex - 1, m_keyframeIndex);
+
transitionToNextInputSourceState();
}
@@ -229,12 +235,20 @@
SimulatedInputSourceState& a = inputSource.state;
SimulatedInputSourceState& b = newState;
- AutomationCompletionHandler eventDispatchFinished = [&inputSource, &newState, completionHandler = WTFMove(completionHandler)](std::optional<AutomationCommandError> error) mutable {
+ LOG(Automation, "SimulatedInputDispatcher[%p]: transition started between input source states: [%d.%d] --> %d.%d", this, m_keyframeIndex - 1, m_inputSourceStateIndex, m_keyframeIndex, m_inputSourceStateIndex);
+
+ AutomationCompletionHandler eventDispatchFinished = [this, &inputSource, &newState, completionHandler = WTFMove(completionHandler)](std::optional<AutomationCommandError> error) mutable {
if (error) {
completionHandler(error);
return;
}
+#if !LOG_DISABLED
+ LOG(Automation, "SimulatedInputDispatcher[%p]: transition finished between input source states: %d.%d --> [%d.%d]", this, m_keyframeIndex - 1, m_inputSourceStateIndex, m_keyframeIndex, m_inputSourceStateIndex);
+#else
+ UNUSED_PARAM(this);
+#endif
+
inputSource.state = newState;
completionHandler(std::nullopt);
};
@@ -253,11 +267,20 @@
RELEASE_ASSERT(location);
b.location = location;
// The "dispatch a pointer{Down,Up,Move} action" algorithms (§17.4 Dispatching Actions).
- if (!a.pressedMouseButton && b.pressedMouseButton)
+ if (!a.pressedMouseButton && b.pressedMouseButton) {
+#if !LOG_DISABLED
+ String mouseButtonName = Inspector::Protocol::AutomationHelpers::getEnumConstantValue(b.pressedMouseButton.value());
+ LOG(Automation, "SimulatedInputDispatcher[%p]: simulating MouseDown[button=%s] for transition to %d.%d", this, mouseButtonName.utf8().data(), m_keyframeIndex, m_inputSourceStateIndex);
+#endif
m_client.simulateMouseInteraction(m_page, MouseInteraction::Down, b.pressedMouseButton.value(), b.location.value(), WTFMove(eventDispatchFinished));
- else if (a.pressedMouseButton && !b.pressedMouseButton)
+ } else if (a.pressedMouseButton && !b.pressedMouseButton) {
+#if !LOG_DISABLED
+ String mouseButtonName = Inspector::Protocol::AutomationHelpers::getEnumConstantValue(a.pressedMouseButton.value());
+ LOG(Automation, "SimulatedInputDispatcher[%p]: simulating MouseUp[button=%s] for transition to %d.%d", this, mouseButtonName.utf8().data(), m_keyframeIndex, m_inputSourceStateIndex);
+#endif
m_client.simulateMouseInteraction(m_page, MouseInteraction::Up, a.pressedMouseButton.value(), b.location.value(), WTFMove(eventDispatchFinished));
- else if (a.location != b.location) {
+ } else if (a.location != b.location) {
+ LOG(Automation, "SimulatedInputDispatcher[%p]: simulating MouseMove for transition to %d.%d", this, m_keyframeIndex, m_inputSourceStateIndex);
// FIXME: This does not interpolate mousemoves per the "perform a pointer move" algorithm (§17.4 Dispatching Actions).
m_client.simulateMouseInteraction(m_page, MouseInteraction::Move, b.pressedMouseButton.value_or(MouseButton::NoButton), b.location.value(), WTFMove(eventDispatchFinished));
} else
@@ -267,19 +290,31 @@
}
case SimulatedInputSourceType::Keyboard:
// The "dispatch a key{Down,Up} action" algorithms (§17.4 Dispatching Actions).
- if (!a.pressedCharKey && b.pressedCharKey)
+ if (!a.pressedCharKey && b.pressedCharKey) {
+ LOG(Automation, "SimulatedInputDispatcher[%p]: simulating KeyPress[key=%c] for transition to %d.%d", this, b.pressedCharKey.value(), m_keyframeIndex, m_inputSourceStateIndex);
m_client.simulateKeyboardInteraction(m_page, KeyboardInteraction::KeyPress, b.pressedCharKey.value(), WTFMove(eventDispatchFinished));
- else if (a.pressedCharKey && !b.pressedCharKey)
+ } else if (a.pressedCharKey && !b.pressedCharKey) {
+ LOG(Automation, "SimulatedInputDispatcher[%p]: simulating KeyRelease[key=%c] for transition to %d.%d", this, a.pressedCharKey.value(), m_keyframeIndex, m_inputSourceStateIndex);
m_client.simulateKeyboardInteraction(m_page, KeyboardInteraction::KeyRelease, a.pressedCharKey.value(), WTFMove(eventDispatchFinished));
- else if (a.pressedVirtualKeys != b.pressedVirtualKeys) {
+ } else if (a.pressedVirtualKeys != b.pressedVirtualKeys) {
for (VirtualKey key : b.pressedVirtualKeys) {
- if (!a.pressedVirtualKeys.contains(key))
+ if (!a.pressedVirtualKeys.contains(key)) {
+#if !LOG_DISABLED
+ String virtualKeyName = Inspector::Protocol::AutomationHelpers::getEnumConstantValue(key);
+ LOG(Automation, "SimulatedInputDispatcher[%p]: simulating KeyPress[key=%s] for transition to %d.%d", this, virtualKeyName.utf8().data(), m_keyframeIndex, m_inputSourceStateIndex);
+#endif
m_client.simulateKeyboardInteraction(m_page, KeyboardInteraction::KeyPress, key, WTFMove(eventDispatchFinished));
+ }
}
for (VirtualKey key : a.pressedVirtualKeys) {
- if (!b.pressedVirtualKeys.contains(key))
+ if (!b.pressedVirtualKeys.contains(key)) {
+#if !LOG_DISABLED
+ String virtualKeyName = Inspector::Protocol::AutomationHelpers::getEnumConstantValue(key);
+ LOG(Automation, "SimulatedInputDispatcher[%p]: simulating KeyRelease[key=%s] for transition to %d.%d", this, virtualKeyName.utf8().data(), m_keyframeIndex, m_inputSourceStateIndex);
+#endif
m_client.simulateKeyboardInteraction(m_page, KeyboardInteraction::KeyRelease, key, WTFMove(eventDispatchFinished));
+ }
}
} else
eventDispatchFinished(std::nullopt);
@@ -311,6 +346,8 @@
m_keyframes.append(SimulatedInputKeyFrame::keyFrameFromStateOfInputSources(m_inputSources));
m_keyframes.appendVector(WTFMove(keyFrames));
+ LOG(Automation, "SimulatedInputDispatcher[%p]: starting input simulation using %d keyframes", this, m_keyframeIndex);
+
transitionToNextKeyFrame();
}
@@ -328,6 +365,8 @@
{
m_keyFrameTransitionDurationTimer.stop();
+ LOG(Automation, "SimulatedInputDispatcher[%p]: finished all input simulation at [%u.%u]", this, m_keyframeIndex, m_inputSourceStateIndex);
+
auto finish = std::exchange(m_runCompletionHandler, nullptr);
m_frameID = std::nullopt;
m_keyframes.clear();
Modified: trunk/Source/WebKit/UIProcess/Automation/WebAutomationSession.cpp (236938 => 236939)
--- trunk/Source/WebKit/UIProcess/Automation/WebAutomationSession.cpp 2018-10-08 20:37:26 UTC (rev 236938)
+++ trunk/Source/WebKit/UIProcess/Automation/WebAutomationSession.cpp 2018-10-08 21:02:20 UTC (rev 236939)
@@ -1503,7 +1503,14 @@
platformSimulateKeyboardInteraction(page, interaction, WTFMove(key));
- // Wait for keyboardEventsFlushedCallback to run when all events are handled.
+ // If the interaction does not generate any events, then do not wait for events to be flushed.
+ // This happens in some corner cases on macOS, such as releasing a key while Command is pressed.
+ if (callbackInMap && !page.isProcessingKeyboardEvents()) {
+ auto callbackToCancel = m_pendingKeyboardEventsFlushedCallbacksPerPage.take(page.pageID());
+ callbackToCancel(std::nullopt);
+ }
+
+ // Otherwise, wait for keyboardEventsFlushedCallback to run when all events are handled.
}
#if USE(APPKIT) || PLATFORM(GTK) || PLATFORM(WPE)
Modified: trunk/Source/WebKit/UIProcess/Automation/mac/WebAutomationSessionMac.mm (236938 => 236939)
--- trunk/Source/WebKit/UIProcess/Automation/mac/WebAutomationSessionMac.mm 2018-10-08 20:37:26 UTC (rev 236938)
+++ trunk/Source/WebKit/UIProcess/Automation/mac/WebAutomationSessionMac.mm 2018-10-08 21:02:20 UTC (rev 236939)
@@ -28,6 +28,7 @@
#if PLATFORM(MAC)
+#import "Logging.h"
#import "WebAutomationSessionMacros.h"
#import "WebInspectorProxy.h"
#import "WebPageProxy.h"
@@ -74,6 +75,8 @@
NSWindow *window = page.platformWindow();
for (NSEvent *event in eventsToSend) {
+ LOG(Automation, "Sending event[%p] to window[%p]: %@", event, window, event);
+
// Take focus back in case the Inspector became focused while the prior command or
// NSEvent was delivered to the window.
[window becomeKeyWindow];
@@ -612,6 +615,12 @@
case KeyboardInteraction::KeyRelease: {
NSEventType eventType = isStickyModifier ? NSEventTypeFlagsChanged : NSEventTypeKeyUp;
m_currentModifiers &= ~changedModifiers;
+
+ // When using a physical keyboard, if command is held down, releasing a non-modifier key doesn't send a KeyUp event.
+ bool commandKeyHeldDown = m_currentModifiers & NSEventModifierFlagCommand;
+ if (characters && commandKeyHeldDown)
+ break;
+
[eventsToBeSent addObject:[NSEvent keyEventWithType:eventType location:eventPosition modifierFlags:m_currentModifiers timestamp:timestamp windowNumber:windowNumber context:nil characters:characters charactersIgnoringModifiers:unmodifiedCharacters isARepeat:NO keyCode:keyCode]];
break;
}
Modified: trunk/Source/WebKit/UIProcess/WebPageProxy.cpp (236938 => 236939)
--- trunk/Source/WebKit/UIProcess/WebPageProxy.cpp 2018-10-08 20:37:26 UTC (rev 236938)
+++ trunk/Source/WebKit/UIProcess/WebPageProxy.cpp 2018-10-08 21:02:20 UTC (rev 236939)
@@ -5114,6 +5114,11 @@
m_process->send(Messages::WebPage::SetTextForActivePopupMenu(index), m_pageID);
}
+bool WebPageProxy::isProcessingKeyboardEvents() const
+{
+ return !m_keyEventQueue.isEmpty();
+}
+
bool WebPageProxy::isProcessingMouseEvents() const
{
return !m_mouseEventQueue.isEmpty();
Modified: trunk/Source/WebKit/UIProcess/WebPageProxy.h (236938 => 236939)
--- trunk/Source/WebKit/UIProcess/WebPageProxy.h 2018-10-08 20:37:26 UTC (rev 236938)
+++ trunk/Source/WebKit/UIProcess/WebPageProxy.h 2018-10-08 21:02:20 UTC (rev 236939)
@@ -737,6 +737,8 @@
void handleMouseEvent(const NativeWebMouseEvent&);
void handleWheelEvent(const NativeWebWheelEvent&);
+
+ bool isProcessingKeyboardEvents() const;
void handleKeyboardEvent(const NativeWebKeyboardEvent&);
#if ENABLE(MAC_GESTURE_EVENTS)
_______________________________________________ webkit-changes mailing list webkit-changes@lists.webkit.org https://lists.webkit.org/mailman/listinfo/webkit-changes
