Debug logging in Guacamole?

[Greg Trasuk <tr...@stratuscom.com>]

I’m trying to dig in to https://issues.apache.org/jira/browse/GUACAMOLE-447, the extraneous keyboard repeat issue on iOS.  I have figured out how to attach a developer console to Safari while running on the iPad.  

Is there a simple way to turn on event logging to see what the Guac client is sending?  I’ll dig in to the source code, but if you’ve already figured out how to setup the client for debugging then that will save some time.

By the way, the problem is consistent.  It also happens in the iPad simulator in Xcode, but does not occur in Safari running on the Mac itself in OSX.

- open ‘vi’ in an ‘ssh’ session
- press ‘i’ to go to insert mode.  Type a few characters, everything is fine.  Press ‘ESC’ to exit the input mode.
- press ‘o’ to go to insert mode (for non-‘vi’-ers this moves the lines following the cursor position down by one line, opening an empty line to type on.
- Don’t touch anything else… after a couple of seconds, you see ‘o’s filling the line.

Curiously, the same thing happens in a ‘vnc’ session.

As Mike pointed out, it makes very little sense, as ‘vi’ should just be responding to characters.  I’m wondering if the issue is something to do with the fact that ‘o’ causes an immediate redraw of half the screen.  I’m thinking that the flood of output somehow causes the client to _not_ send the keyup code for ‘o’, or perhaps causes the proxy to miss something.  Or some delay somewhere puts guacd into ‘repeat key’ mode, where it gets stuck.  There are a lot of possibilities, so I’d like to get some visibility into the event stream to narrow them down.

Cheers,

Greg Trasuk

Re: Debug logging in Guacamole?

[Mike Jumper <mi...@guac-dev.org>]

On Mon, Dec 11, 2017 at 8:51 AM, Greg Trasuk <tr...@stratuscom.com> wrote:

>
> I’m trying to dig in to https://issues.apache.org/jira
> /browse/GUACAMOLE-447, the extraneous keyboard repeat issue on iOS.  I
> have figured out how to attach a developer console to Safari while running
> on the iPad.
>
> Is there a simple way to turn on event logging to see what the Guac client
> is sending?  I’ll dig in to the source code, but if you’ve already figured
> out how to setup the client for debugging then that will save some time.
>
>
There is no such mechanism built into the web application, however you can
add such logging by adding the necessary console.log() statements to within
the "onkeyup" and "onkeydown" handlers set on the Guacamole.Keyboard object
within the web application. Given the likelihood that this is a bug in the
way Safari is dispatching JavaScript key events, I would recommend adding
this logging within the Guacamole.Keyboard object itself, logging both (1)
received JavaScript key events and (2) Guacamole's interpretation of those
events.

Low-level JS event handling: https://github.com/apache/guac
amole-client/blob/4a9560358bc5043444c8e4e27b648199e1d6a682/
guacamole-common-js/src/main/webapp/modules/Keyboard.js#L1039-L1110

Functions called as a result of Guacamole event interpretation:
https://github.com/apache/guacamole-client/blob/4a9560358bc5043444c8e4e27
b648199e1d6a682/guacamole-common-js/src/main/webapp/
modules/Keyboard.js#L715-L785

By the way, the problem is consistent.  It also happens in the iPad
> simulator in Xcode, but does not occur in Safari running on the Mac itself
> in OSX.
>
> - open ‘vi’ in an ‘ssh’ session
> - press ‘i’ to go to insert mode.  Type a few characters, everything is
> fine.  Press ‘ESC’ to exit the input mode.
> - press ‘o’ to go to insert mode (for non-‘vi’-ers this moves the lines
> following the cursor position down by one line, opening an empty line to
> type on.
> - Don’t touch anything else… after a couple of seconds, you see ‘o’s
> filling the line.
>
>
This sounds like iOS Safari is not dispatching the JavaScript keyup at all,
and thus Guacamole's built-in key repeat kicks in (since, as far as
Guacamole knows, you are still holding down the key).

Curiously, the same thing happens in a ‘vnc’ session.
>
>
This is a good sign. The browser side of things has no concept of what
application nor what protocol you're using. At that level, everything is
just Guacamole protocol, and the same key event handling applies. If the
problem were isolated to a specific application within SSH, that would be
strange, however the fact that this occurs regardless of application,
regardless of protocol, as long as you're using an iPad or iPad simulator
means that this is very likely due to strange JavaScript key events
dispatching on Safari's part.

As Mike pointed out, it makes very little sense, as ‘vi’ should just be
> responding to characters.  I’m wondering if the issue is something to do
> with the fact that ‘o’ causes an immediate redraw of half the screen.  I’m
> thinking that the flood of output somehow causes the client to _not_ send
> the keyup code for ‘o’, or perhaps causes the proxy to miss something.  Or
> some delay somewhere puts guacd into ‘repeat key’ mode, where it gets
> stuck.  There are a lot of possibilities, so I’d like to get some
> visibility into the event stream to narrow them down.
>
>
Nope. Even if typing an "o" causes a large change to the screen, key events
within JavaScript are dispatched in a queue. Guacamole interprets those
events as they are dispatched, streaming the result of that interpretation
to the server. The only ways that a key release could be missed are:

1) Guacamole's key event interpretation has a bug which is causing it to
ignore the key release
2) Guacamole's key event interpretation has a bug which is causing the key
release to not properly reset the key repeat state
3) iOS Safari (or perhaps iOS itself) has a bug which is causing the key
release to never occur

Guacamole's key handling does have a built-in key repeat mode on the client
side, as not all browsers will automatically repeat keys which are held,
but that repeating state is cleared upon key release.

For what it's worth, it's also unlikely that Guacamole is producing a flood
of output in response to scrolling half the screen down. While the
client-side result will be that half the screen changes, the change itself
will likely be encoded as a copy of the scrolled part downward, with new
image data sent only for the parts of the screen which are changing. Trying
this myself on a test text file with the network tab of dev tools open, I
see the following images received:

1) The updated line/column coordinates
2) The text "-- INSERT --"
3) The character which was under the cursor but is now no longer highlighted
4) The blank character which now has the cursor

The rest of the changes are a copy of the existing data downward (no new
image data sent) and a black rectangle clearing the line which now contains
the cursor (sent as a "rect" instruction rather than an image). Overall,
not very much data at all.

If you'd like an even more low-level log of things, I have been working on
adding input event logging to Guacamole's existing session recording
functionality on the "input-log" branch of my GitHub forks of
guacamole-client and guacamole-server:

https://github.com/mike-jumper/guacamole-client/tree/input-log
https://github.com/mike-jumper/guacamole-server/tree/input-log

You'd need to rebase/merge the guacamole-client on top of the iOS escape
key fix, but the above changes would allow you to include key events
alongside the graphics normally recorded when session recording is enabled.
An additional utility called "guaclog", part of guacamole-server, can be
used to interpret the key events within the recording and produce a
human-readable text file. You can also look through the "key" instructions
within the raw recording, as it is just Guacamole protocol, and is thus
text.

Thanks,

- Mike