Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Rapid touch inputs on the OSK produce inconsistent output #818

Closed
jahorton opened this issue May 4, 2018 · 11 comments
Closed

Rapid touch inputs on the OSK produce inconsistent output #818

jahorton opened this issue May 4, 2018 · 11 comments

Comments

@jahorton
Copy link
Contributor

jahorton commented May 4, 2018

This issue also affects our Android and iOS products, so it's rather critical.

Once thought to affect all of KeymanWeb mobile + embedded, it turns out this particular error pattern happens solely within the iOS app.

Basically, what the title says - pressing two keys on a keyboard within a very tight timeframe leads to rather inconsistent output. Sometimes one of the two keys will have its output doubled, sometimes only one key is output once, etc. It's almost certainly something in the way that touch-event handlers are processing keyboard input, hampering Keyman's usability.

@jahorton
Copy link
Contributor Author

jahorton commented May 4, 2018

Interesting... there are some differences among the platforms.

iOS suffers far more from this issues than does native KMW... there must be something in the iOS app causing this. Additionally, I can get the popup preview key from iOS to stick in situations where I cannot do so in native KMW.

@jahorton
Copy link
Contributor Author

jahorton commented May 4, 2018

iOS app preview key instructions:

Type the following keys in sequence on the default EuroLatin2 keyboard, only releasing each key after the next key in the sequence has been pressed. Go at a moderate speed, just quick enough to avoid generating the long-press menu:

  • 'a'
  • 'l'
  • 's'
  • 'k'
  • 'd'
  • 'j'

Upon releasing the 'j' in a similar manner to the others, you should see the 'j' key's preview remain if input was well-timed, while also seeing the full output string 'alskdj' in the text area.

This should generalize to other keyboards and keystroke patterns - I simply chose this pattern for ease of typing and general readability.


Chances are, when keystrokes get sped up, something similar to this preview bug's cause likely underlies the overall issue for the iOS app.

@jahorton jahorton removed the web/ label May 7, 2018
@jahorton
Copy link
Contributor Author

jahorton commented May 7, 2018

Further testing and attempts at reproduction suggest that this is solely an iOS thing.

@jahorton jahorton modified the milestones: P3S3, 10.0-stable May 7, 2018
@jahorton jahorton changed the title KMW Mobile-mode: Rapid touch inputs on the OSK produce inconsistent output Rapid touch inputs on the OSK produce inconsistent output May 7, 2018
@jahorton jahorton modified the milestones: 10.0-stable, P3S3 May 7, 2018
@jahorton
Copy link
Contributor Author

jahorton commented May 9, 2018

To test out this hypothesis further, I used one of our test iPads. After all, 'phone' form factor devices use key previews while 'tablet' form factor devices do not, all within the same version of the app.

iPad (no key preview):

  • very little input error
  • mostly due to personal mistyping
  • there do exist dead zones between keys that can cause problems if I fatfinger a key or two.

iPhone (with key preview):

  • considerable input error
  • the key previews can't keep up with my typing speed (now that I'm looking for them)
  • the key previews that show do seem to indicate which keys get processed.

On a side note, I did get to see one issue highly related to #716 in action by accident when clearing the text area. I'll document it there.

@jahorton
Copy link
Contributor Author

jahorton commented May 9, 2018

On the other hand, I just ran another test using our test iPhone 5c, having neutered the key previews. That is, I blocked the embedded osk.showKeyTip's access to the preview-generation function hooks. This 'phone' form factor test with the preview display disabled still suffered from the rapid-input issue. (As if it still had 'key preview' enabled, from the previous experiment's notes.)

That seemed odd, so I went on to run another test. Same device, but this time I forced the embedded KMW to believe the phone was a 'tablet' so that it would never even attempt to generate key previews.

It turns out that the iPhone 5c still suffers the same issues; there's some clear lag in how it attempts to handle input events.

@jahorton
Copy link
Contributor Author

OK. Rigged up an event-logging embedded variant of KMW to get us a better look at what's happening.

The 'touchstart' and 'touchend' handlers both are rigged to report which touch point is most relevant for the event, and osk.clickKey is rigged to report whenever a key is considered 'clicked' and when that key is sent to rule processing.

Intended input: "the quick brown fox"
Actual input: rhw quick briwn fx due to minor fat-fingering.
Actual output: rrw uick bwn x

It appears that the 'r' of 'brown' and the 'o' of 'fox' were not detected for some reason. Other errors arose from other sources.

The result, from Xcode logs of an on-device iPhone 5c experiment run:

2018-05-10 13:00:48.584 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_R'
2018-05-10 13:00:48.674 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Move
2018-05-10 13:00:48.692 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_R'
2018-05-10 13:00:48.787 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_H'
2018-05-10 13:00:48.793 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_R
2018-05-10 13:00:48.794 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_R
2018-05-10 13:00:48.795 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-63+dn=0+s=0x0072
2018-05-10 13:00:48.803 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_R
2018-05-10 13:00:48.823 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_R
2018-05-10 13:00:48.838 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-64+dn=0+s=0x0072
2018-05-10 13:00:48.851 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_W'
2018-05-10 13:00:48.877 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Move
2018-05-10 13:00:48.885 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_H'
2018-05-10 13:00:48.893 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_W
2018-05-10 13:00:48.902 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_W
2018-05-10 13:00:48.920 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-67+dn=0+s=0x0077
2018-05-10 13:00:48.941 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_W'
2018-05-10 13:00:48.971 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_SPACE'
2018-05-10 13:00:49.060 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_SPACE'
2018-05-10 13:00:49.104 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_SPACE
2018-05-10 13:00:49.105 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_Q'
2018-05-10 13:00:49.111 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_SPACE
2018-05-10 13:00:49.112 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_SPACE
2018-05-10 13:00:49.113 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-70+dn=0+s=0x0020
2018-05-10 13:00:49.120 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_SPACE
2018-05-10 13:00:49.148 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-71+dn=0+s=0x0020
2018-05-10 13:00:49.192 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_Q'
2018-05-10 13:00:49.220 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_U'
2018-05-10 13:00:49.307 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_U'
2018-05-10 13:00:49.320 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_U
2018-05-10 13:00:49.327 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_U
2018-05-10 13:00:49.340 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-76+dn=0+s=0x0075
2018-05-10 13:00:49.404 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_I'
2018-05-10 13:00:49.474 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_I'
2018-05-10 13:00:49.484 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_I
2018-05-10 13:00:49.492 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_I
2018-05-10 13:00:49.525 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-80+dn=0+s=0x0069
2018-05-10 13:00:49.543 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_C'
2018-05-10 13:00:49.611 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_K'
2018-05-10 13:00:49.634 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_C
2018-05-10 13:00:49.644 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_C
2018-05-10 13:00:49.656 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-84+dn=0+s=0x0063
2018-05-10 13:00:49.672 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_C'
2018-05-10 13:00:49.687 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_K
2018-05-10 13:00:49.693 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_K
2018-05-10 13:00:49.704 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-86+dn=0+s=0x006B
2018-05-10 13:00:49.714 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_K'
2018-05-10 13:00:49.819 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_SPACE'
2018-05-10 13:00:49.907 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_SPACE'
2018-05-10 13:00:49.914 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_SPACE
2018-05-10 13:00:49.921 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_SPACE
2018-05-10 13:00:49.935 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-88+dn=0+s=0x0020
2018-05-10 13:00:50.307 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_B'
2018-05-10 13:00:50.422 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: ERROR: Script error. URL: L:0
2018-05-10 13:00:50.422 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: ERROR: Script error. URL: L:0
2018-05-10 13:00:50.423 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_I'
2018-05-10 13:00:50.428 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_B
2018-05-10 13:00:50.428 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_B
2018-05-10 13:00:50.429 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-92+dn=0+s=0x0062
2018-05-10 13:00:50.441 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_I'
2018-05-10 13:00:50.442 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_W'
2018-05-10 13:00:50.449 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_B'
2018-05-10 13:00:50.462 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_W
2018-05-10 13:00:50.474 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_W
2018-05-10 13:00:50.513 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-97+dn=0+s=0x0077
2018-05-10 13:00:50.524 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_N'
2018-05-10 13:00:50.533 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_W'
2018-05-10 13:00:50.548 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_N
2018-05-10 13:00:50.557 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_N
2018-05-10 13:00:50.573 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-1+dn=0+s=0x006E
2018-05-10 13:00:50.588 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_N'
2018-05-10 13:00:50.694 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_SPACE'
2018-05-10 13:00:50.759 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_SPACE'
2018-05-10 13:00:50.806 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_SPACE
2018-05-10 13:00:50.808 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_F'
2018-05-10 13:00:50.814 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_SPACE
2018-05-10 13:00:50.815 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_SPACE
2018-05-10 13:00:50.816 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-4+dn=0+s=0x0020
2018-05-10 13:00:50.827 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_SPACE
2018-05-10 13:00:50.839 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-5+dn=0+s=0x0020
2018-05-10 13:00:50.917 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: ERROR: Script error. URL: L:0
2018-05-10 13:00:50.922 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_F'
2018-05-10 13:00:51.009 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: ERROR: Script error. URL: L:0
2018-05-10 13:00:51.070 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_X'
2018-05-10 13:00:51.156 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_X'
2018-05-10 13:00:51.168 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_X
2018-05-10 13:00:51.177 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_X
2018-05-10 13:00:51.189 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-10+dn=0+s=0x0078

It would appear that osk.clickKey isn't being sent the correct information during rapid input at times. The existing event-handling design is such that for the sequence "ab", osk.clickKey is called for "a" when "b" is pressed or when "a" is released (whichever is first) and called for "b" when "b" is released.

It'll take some time to analyze this log more thoroughly, but what is alarming is that certain events that should occur sequentially in a synchronous manner appear to have other events transpiring in the middle of their code.

@jahorton
Copy link
Contributor Author

For comparison, the same "actual input" typed far more slowly, resulting in correct output:

2018-05-10 13:32:39.968 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_R'
2018-05-10 13:32:40.055 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_R'
2018-05-10 13:32:40.067 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_R
2018-05-10 13:32:40.076 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_R
2018-05-10 13:32:40.133 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-4+dn=0+s=0x0072
2018-05-10 13:32:40.401 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_H'
2018-05-10 13:32:40.520 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_H'
2018-05-10 13:32:40.543 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_H
2018-05-10 13:32:40.550 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_H
2018-05-10 13:32:40.574 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-8+dn=0+s=0x0068
2018-05-10 13:32:40.983 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_W'
2018-05-10 13:32:41.113 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_W'
2018-05-10 13:32:41.126 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_W
2018-05-10 13:32:41.134 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_W
2018-05-10 13:32:41.145 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-12+dn=0+s=0x0077
2018-05-10 13:32:41.814 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_SPACE'
2018-05-10 13:32:41.971 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_SPACE'
2018-05-10 13:32:41.977 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_SPACE
2018-05-10 13:32:41.984 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_SPACE
2018-05-10 13:32:41.999 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-14+dn=0+s=0x0020
2018-05-10 13:32:42.508 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_Q'
2018-05-10 13:32:42.636 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_Q'
2018-05-10 13:32:42.647 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_Q
2018-05-10 13:32:42.653 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_Q
2018-05-10 13:32:42.666 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-18+dn=0+s=0x0071
2018-05-10 13:32:42.950 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_U'
2018-05-10 13:32:43.037 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_U'
2018-05-10 13:32:43.048 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_U
2018-05-10 13:32:43.055 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_U
2018-05-10 13:32:43.067 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-22+dn=0+s=0x0075
2018-05-10 13:32:43.400 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_I'
2018-05-10 13:32:43.486 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_I'
2018-05-10 13:32:43.497 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_I
2018-05-10 13:32:43.505 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_I
2018-05-10 13:32:43.527 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-26+dn=0+s=0x0069
2018-05-10 13:32:43.835 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_C'
2018-05-10 13:32:43.953 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_C'
2018-05-10 13:32:43.964 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_C
2018-05-10 13:32:43.970 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_C
2018-05-10 13:32:43.982 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-30+dn=0+s=0x0063
2018-05-10 13:32:44.300 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_K'
2018-05-10 13:32:44.420 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_K'
2018-05-10 13:32:44.431 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_K
2018-05-10 13:32:44.437 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_K
2018-05-10 13:32:44.446 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-34+dn=0+s=0x006B
2018-05-10 13:32:44.757 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_SPACE'
2018-05-10 13:32:44.871 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_SPACE'
2018-05-10 13:32:44.878 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_SPACE
2018-05-10 13:32:44.884 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_SPACE
2018-05-10 13:32:44.900 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-36+dn=0+s=0x0020
2018-05-10 13:32:47.194 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_B'
2018-05-10 13:32:47.337 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_B'
2018-05-10 13:32:47.346 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_B
2018-05-10 13:32:47.354 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_B
2018-05-10 13:32:47.365 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-40+dn=0+s=0x0062
2018-05-10 13:32:47.683 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_R'
2018-05-10 13:32:47.854 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_R'
2018-05-10 13:32:47.864 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_R
2018-05-10 13:32:47.871 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_R
2018-05-10 13:32:47.886 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-44+dn=0+s=0x0072
2018-05-10 13:32:48.228 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_I'
2018-05-10 13:32:48.337 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_I'
2018-05-10 13:32:48.348 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_I
2018-05-10 13:32:48.358 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_I
2018-05-10 13:32:48.370 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-48+dn=0+s=0x0069
2018-05-10 13:32:48.749 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_W'
2018-05-10 13:32:48.870 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_W'
2018-05-10 13:32:48.882 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_W
2018-05-10 13:32:48.890 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_W
2018-05-10 13:32:48.904 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-52+dn=0+s=0x0077
2018-05-10 13:32:49.477 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_N'
2018-05-10 13:32:49.602 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_N'
2018-05-10 13:32:49.614 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_N
2018-05-10 13:32:49.621 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_N
2018-05-10 13:32:49.634 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-56+dn=0+s=0x006E
2018-05-10 13:32:50.740 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_SPACE'
2018-05-10 13:32:50.872 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_SPACE'
2018-05-10 13:32:50.879 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_SPACE
2018-05-10 13:32:50.885 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_SPACE
2018-05-10 13:32:50.899 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-58+dn=0+s=0x0020
2018-05-10 13:32:51.553 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_F'
2018-05-10 13:32:51.704 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_F'
2018-05-10 13:32:51.715 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_F
2018-05-10 13:32:51.722 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_F
2018-05-10 13:32:51.734 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-62+dn=0+s=0x0066
2018-05-10 13:32:52.208 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_O'
2018-05-10 13:32:52.336 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_O'
2018-05-10 13:32:52.347 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_O
2018-05-10 13:32:52.354 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_O
2018-05-10 13:32:52.367 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-66+dn=0+s=0x006F
2018-05-10 13:32:52.683 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] start:  key = 'default-K_X'
2018-05-10 13:32:52.770 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] end:  key = 'default-K_X'
2018-05-10 13:32:52.781 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Clicked key: default-K_X
2018-05-10 13:32:52.787 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] Starting keystroke processing for key default-K_X
2018-05-10 13:32:52.800 [Info] [KeymanWebViewController.swift:285] userContentController(_:didReceive:) > KMW Log: [Touch] #insertText-70+dn=0+s=0x0078

@jahorton jahorton added the web/ label May 10, 2018
@jahorton
Copy link
Contributor Author

jahorton commented May 10, 2018

Noting the information on https://docs.kioskproapp.com/article/840-wkwebview-supported-features-known-issues, we know that the WKWebView operates asynchronously from the iOS app and that JavaScript calls across the barrier themselves are also asynchronous. It's quite possible that the order of events in the "rapid touch" log are out of order due to logging race conditions... but it would appear that this cannot be the only asynchronous oddity in the logs above.

I'm hesitant to say this, but it looks like the touch event handlers themselves are operating asynchronously, possibly in parallel with each other.

Consider the following block from the "rapid touch" log, with irrelevant info omitted:

13:00:48.584 > start:  key = 'default-K_R'
13:00:48.692 > end:  key = 'default-K_R'
13:00:48.787 > start:  key = 'default-K_H'
13:00:48.793 > Clicked key: default-K_R
13:00:48.794 > Starting keystroke processing for key default-K_R
13:00:48.795 > #insertText-63+dn=0+s=0x0072
13:00:48.803 > Clicked key: default-K_R
13:00:48.823 > Starting keystroke processing for key default-K_R
13:00:48.838 > #insertText-64+dn=0+s=0x0072
13:00:48.851 > start:  key = 'default-K_W'
13:00:48.885 > end:  key = 'default-K_H'
13:00:48.893 > Clicked key: default-K_W
13:00:48.902 > Starting keystroke processing for key default-K_W
13:00:48.920 > #insertText-67+dn=0+s=0x0077
13:00:48.941 > end:  key = 'default-K_W'

Suppose, for a moment, that we could assume these log messages all occurred sequentially, with no race conditioning reordering involved.

If we start with this assumption, then the third and fourth lines appear to be out of order - the second line (end: key = 'default-K_R'`) should have immediately triggered the fourth line, as that log message is in a function called by the same function giving the second line's log.

If we assumed instead that these lines were merely reordered due to asynchronous logging, however, that gives us a major question for the seventh line (timestamp 13:00:48.803): where did the second Clicked key: default-K_R come from? We hadn't released the second key that we pressed yet, so there should not be a second osk.clickKey call!

If we instead operate from the original assumption, we have a valid explanation... but it's bad news. If the third line's function reaches a certain point before the second line's function reaches its critical point, regarding the property osk.keyPending, the following would be a valid chronological ordering of events:

  1. Line 2's function (osk.touch) begins processing on thread A, which is paused.
  2. Line 3's function (osk.release) begins and completes processing on thread B, which continues.
  3. Lines 4 through 6 are from thread B, having been triggered by osk.release on the osk.keyPending value 'default-K_R`.
  4. Lines 7 through 9: Before thread B completes its osk.clickKey and sets osk.keyPending = null, thread B pauses while A wakes up, seeing that 'default-K_R' is still pending.
  • It calls osk.clickKey for 'default-K_R' as a result.
  • It then sets osk.keyPending to 'default-K_H' after finishing.
  1. Before line 10 (timestamp 13:00:48.851): thread B resumes, erasing osk.keyPending. As a result, 'default-K_H' is never processed by osk.clickKey().
  • Without this erasure, we'd still get a 'H' after the the doubled 'R' - and I have seen this behavior with other repro attempts for this issue!
  1. Line 10 sets osk.keyPending to 'default-K_W'.
  2. ... which is then handled by Line 11's end for 'K_H', which fully completes and erases osk.keyPending
  3. Final line - no output results, since osk.keyPending is already empty.

I'd love to find a logical explanation on how this result could be reached without the governing assumption that the log messages are, in fact, synchronous and perfectly chronologically ordered. The implications of that assumption being correct have serious consequences - namely, that we can't trust the WKWebView to execute internally-sourced JavaScript calls sequentially, from a single event message queue, within a single thread - which appears to be the default behavior within standard browsers. But I can't find a reasonable alternate explanation, let alone a 'simpler' explanation for this behavior.

@jahorton
Copy link
Contributor Author

One more run in an attempt to further confirm the behavior - this time I put similar logging in place, but this time collated all the log messages within the WebView's embedded page via JS array.push, setting the logs to 'flush' on a two-second timeout that was cleared upon receiving any new messages. Short version: there cannot be any additional asynchronous-ness added by the JS -> Swift barrier to the log messages - it's all perfectly chronological on the embedded, JS side.

[Touch] start:  key = 'default-K_T'
[Touch] end:  key = 'default-K_T'
[Touch] Clicked key: default-K_T
[Touch] Starting keystroke processing for key default-K_T
[Touch] start:  key = 'default-K_H'
[Touch] Clicked key: default-K_T
[Touch] Starting keystroke processing for key default-K_T
[Touch] #insertText-61+dn=0+s=0x0074
[Touch] #insertText-61+dn=0+s=0x0074
[Touch] end:  key = 'default-K_H'
[Touch] start:  key = 'default-K_E'
[Touch] start:  key = 'default-K_SPACE'
[Touch] Clicked key: default-K_E
[Touch] Starting keystroke processing for key default-K_E
[Touch] #insertText-66+dn=0+s=0x0065
[Touch] end:  key = 'default-K_E'
[Touch] Clicked key: default-K_SPACE
[Touch] Starting keystroke processing for key default-K_SPACE
[Touch] #insertText-67+dn=0+s=0x0020
[Touch] end:  key = 'default-K_SPACE'
[Touch] start:  key = 'default-K_Q'
[Touch] Move
[Touch] Move
[Touch] Move
[Touch] Move
[Touch] Move
[Touch] start:  key = 'default-K_U'
[Touch] Clicked key: default-K_Q
[Touch] Starting keystroke processing for key default-K_Q
[Touch] #insertText-71+dn=0+s=0x0071
[Touch] Move
[Touch] end:  key = 'default-K_Q'
[Touch] Clicked key: default-K_U
[Touch] Starting keystroke processing for key default-K_U
[Touch] #insertText-73+dn=0+s=0x0075
[Touch] end:  key = 'default-K_U'
[Touch] start:  key = 'default-K_I'
[Touch] end:  key = 'default-K_I'
[Touch] Clicked key: default-K_I
[Touch] Starting keystroke processing for key default-K_I
[Touch] #insertText-77+dn=0+s=0x0069
ERROR: Script error. URL: L:0
[Touch] start:  key = 'default-K_K'
ERROR: Script error. URL: L:0
[Touch] end:  key = 'default-K_K'
[Touch] Clicked key: default-K_K
[Touch] Starting keystroke processing for key default-K_K
[Touch] #insertText-80+dn=0+s=0x006B
[Touch] start:  key = 'default-K_SPACE'
[Touch] end:  key = 'default-K_SPACE'
[Touch] Clicked key: default-K_SPACE
[Touch] Starting keystroke processing for key default-K_SPACE
[Touch] #insertText-82+dn=0+s=0x0020
[Touch] start:  key = 'default-K_B'
[Touch] end:  key = 'default-K_B'
[Touch] Clicked key: default-K_B
[Touch] Starting keystroke processing for key default-K_B
[Touch] #insertText-86+dn=0+s=0x0062
[Touch] start:  key = 'default-K_B'
[Touch] start:  key = 'default-K_R'
[Touch] Clicked key: default-K_B
[Touch] Starting keystroke processing for key default-K_B
[Touch] #insertText-90+dn=0+s=0x0062
[Touch] end:  key = 'default-K_B'
[Touch] Clicked key: default-K_R
[Touch] Starting keystroke processing for key default-K_R
[Touch] #insertText-92+dn=0+s=0x0072
[Touch] end:  key = 'default-K_R'
[Touch] start:  key = 'default-K_I'
[Touch] end:  key = 'default-K_I'
[Touch] Clicked key: default-K_I
[Touch] Starting keystroke processing for key default-K_I
[Touch] start:  key = 'default-K_Q'
[Touch] Clicked key: default-K_I
[Touch] Starting keystroke processing for key default-K_I
[Touch] #insertText-98+dn=0+s=0x0069
[Touch] #insertText-98+dn=0+s=0x0069
[Touch] end:  key = 'default-K_Q'
ERROR: Script error. URL: L:0
ERROR: Script error. URL: L:0
[Touch] start:  key = 'default-K_SPACE'
[Touch] Move
[Touch] Move
[Touch] Move
[Touch] Move
[Touch] end:  key = 'default-K_SPACE'
[Touch] Clicked key: default-K_SPACE
[Touch] Starting keystroke processing for key default-K_SPACE
[Touch] #insertText-1+dn=0+s=0x0020
[Touch] start:  key = 'default-K_F'
[Touch] start:  key = 'default-K_O'
[Touch] Clicked key: default-K_F
[Touch] Starting keystroke processing for key default-K_F
[Touch] #insertText-5+dn=0+s=0x0066
[Touch] end:  key = 'default-K_F'
[Touch] Clicked key: default-K_O
[Touch] Starting keystroke processing for key default-K_O
[Touch] #insertText-7+dn=0+s=0x006F
[Touch] end:  key = 'default-K_O'
[Touch] start:  key = 'default-K_X'
[Touch] Move
[Touch] Move
[Touch] Move
[Touch] Move
[Touch] end:  key = 'default-K_X'
[Touch] Clicked key: default-K_ENTER
[Touch] Starting keystroke processing for key default-K_ENTER
[Touch] #insertText-11+dn=0+s=0x000A

Note the first few keystrokes - this time, ala race condition, the T's 'end' event did start the processing first... but it didn't clear osk.keyPending in time to prevent the H's 'start' from processing it as well. Interestingly, the alleged threading asynchronous behavior for both events was generated near the same time, as seen by the paired #insertText lines.

Relevant section:

[Touch] start:  key = 'default-K_T'
[Touch] end:  key = 'default-K_T'
[Touch] Clicked key: default-K_T
[Touch] Starting keystroke processing for key default-K_T
[Touch] start:  key = 'default-K_H'
[Touch] Clicked key: default-K_T
[Touch] Starting keystroke processing for key default-K_T
[Touch] #insertText-61+dn=0+s=0x0074
[Touch] #insertText-61+dn=0+s=0x0074

Since we're purely in JS land now, note that each alleged thread must output #insertText before it clears osk.keyPending, as both perform the property clearing after osk.clickKey fully completes. If we were synchronous, there's no way there would be a break between the "Starting keystroke processing" and corresponding "#insertText" lines.

@jahorton
Copy link
Contributor Author

It appears that this behavior is due to legacy use of window.location.hash in our embedded keyboard page; changing this can generate an event interrupting the first.

Nixing this isn't enough to solve all the issues, however, as some of the OSK touch events aren't recognizing the intended key. This has been determined as related to #863.

@mcdurdin
Copy link
Member

Core issue fixed by #865. Between-key presses in #863 can be followed up there. Closing as resolved.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

2 participants