websockify icon indicating copy to clipboard operation
websockify copied to clipboard

Published 20 hours ago • verified publisher icon novnc

When using the --verbose option set root log level to DEBUG

Open javicacheiro opened this issue 2 years ago • 5 comments

When using the --verbose/-v option set root log level to DEBUG

javicacheiro avatar May 03 '22 08:05 javicacheiro

:thinking: is this common practice?

samhed avatar May 04 '22 05:05 samhed

It depends on the external modules that you use and how verbose they are.

In the case of websockify it does not increase the logging messages much and it is quite useful for debugging so I think it is quite convenient and it has no obvious drawbacks.

javicacheiro avatar May 06 '22 09:05 javicacheiro

We seem to have already crossed the bridge of mixing up "debug" and "verbose", so that should not be a blocker here.

But I'm confused about what this PR actually does. What log messages are appearing at different levels of the hierarchy?

CendioOssman avatar May 11 '22 12:05 CendioOssman

Just run the original and the new code with the "--verbose" option and the difference in the output are the following two lines (for one connection):

response from redis : 4.4.4.4:5901
host: 4.4.4.4, port: 5901

So if we look at these two lines in context we get info about the connection obtained from redis:

Resolving token 'TKNXXXXXXXXXXXXXXXX'
response from redis : 4.4.4.4:5901
host: 4.4.4.4, port: 5901

Just as reference I include the full output of the "--verbose" option in both cases. I think the two additional lines in the output are really negligible ;-)

Full output from the original "--verbose" version:

TokenRedis backend initilized (3.3.3:6379)
WebSocket server settings:
  - Listen on 1.1.1.1:9444
  - Web server. Web root: /root/websockify/standalone/novnc/noVNC-1.3.0
  - SSL/TLS support
  - Deny non-SSL/TLS connections
  - proxying from 1.1.1.1:9444 to targets generated by TokenRedis
2.2.2.2: new handler Process
2.2.2.2 - - [16/May/2022 17:04:25] "GET /vnc.html?token=TKNXXXXXXXXXXX&password=00000000&autoconnect=true&path=websockify?token=TKNXXXXXXXXXXX HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/styles/base.css HTTP/1.1" 200 -
2.2.2.2: new handler Process
2.2.2.2: new handler Process
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/error-handler.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/ui.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/images/warning.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/images/info.svg HTTP/1.1" 200 -
2.2.2.2: new handler Process
2.2.2.2: new handler Process
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/images/error.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/images/drag.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/images/keyboard.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/images/toggleextrakeys.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/images/ctrl.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/images/alt.svg HTTP/1.1" 200 -
2.2.2.2: new handler Process
2.2.2.2 - - [16/May/2022 17:04:25] "GET /core/util/logging.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/localization.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /core/util/browser.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /core/util/events.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /core/input/keysym.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/images/windows.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /core/input/keysymdef.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /core/input/keyboard.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /core/rfb.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/webutil.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/styles/Orbitron700.woff HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:25] "GET /app/sounds/bell.oga HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/expander.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/tab.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/esc.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/ctrlaltdel.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/power.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/input/util.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/clipboard.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/connect.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/settings.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/fullscreen.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/disconnect.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/util/int.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/util/strings.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/util/element.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/util/eventtarget.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/display.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/inflator.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/deflator.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/input/gesturehandler.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/util/cursor.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/websock.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/des.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/input/xtscancodes.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/encodings.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/decoders/raw.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/decoders/copyrect.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/decoders/rre.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/decoders/hextile.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/decoders/tight.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/decoders/tightpng.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/input/vkeys.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/input/fixedkeys.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/input/domkeytable.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/zlib/inflate.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /core/base64.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/zlib/zstream.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/zlib/deflate.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/utils/common.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/zlib/adler32.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/zlib/crc32.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/zlib/inffast.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/zlib/inftrees.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/zlib/trees.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /vendor/pako/lib/zlib/messages.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /package.json HTTP/1.1" 200 -
2.2.2.2: new handler Process
Resolving token 'TKNXXXXXXXXXXXXXXXX'
2.2.2.2 - - [16/May/2022 17:04:26] "GET /websockify?token=TKNXXXXXXXXXXX HTTP/1.1" 101 -
2.2.2.2 - - [16/May/2022 17:04:26] 2.2.2.2: SSL/TLS (wss://) WebSocket connection
2.2.2.2 - - [16/May/2022 17:04:26] 2.2.2.2: Path: '/websockify?token=TKNXXXXXXXXXXX'
2.2.2.2 - - [16/May/2022 17:04:26] connecting to: 4.4.4.4:5901
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/icons/novnc-192x192.png HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:26] "GET /app/images/icons/novnc-16x16.png HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:27] "GET /app/images/handle_bg.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:04:27] "GET /app/images/handle.svg HTTP/1.1" 200 -

Full output from the modified "--verbose" version:

TokenRedis backend initilized (3.3.3:6379)
WebSocket server settings:
  - Listen on 1.1.1.1:9444
  - Web server. Web root: /root/websockify/standalone/novnc/noVNC-1.3.0
  - SSL/TLS support
  - Deny non-SSL/TLS connections
  - proxying from 1.1.1.1:9444 to targets generated by TokenRedis
2.2.2.2: new handler Process
2.2.2.2 - - [16/May/2022 17:01:21] "GET /vnc.html?token=TKNXXXXXXXXXXX&password=00000000&autoconnect=true&path=websockify?token=TKNXXXXXXXXXXX HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:21] "GET /app/styles/base.css HTTP/1.1" 200 -
2.2.2.2: new handler Process
2.2.2.2: new handler Process
2.2.2.2 - - [16/May/2022 17:01:21] "GET /app/error-handler.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:21] "GET /app/ui.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:21] "GET /app/images/warning.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:21] "GET /app/images/info.svg HTTP/1.1" 200 -
2.2.2.2: new handler Process
2.2.2.2: new handler Process
2.2.2.2 - - [16/May/2022 17:01:21] "GET /app/images/error.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/drag.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/keyboard.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/toggleextrakeys.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/ctrl.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/alt.svg HTTP/1.1" 200 -
2.2.2.2: new handler Process
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/util/logging.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/localization.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/util/browser.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/util/events.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/input/keysym.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/windows.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/input/keysymdef.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/input/keyboard.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/webutil.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/styles/Orbitron700.woff HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/rfb.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/sounds/bell.oga HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/expander.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/tab.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/esc.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/ctrlaltdel.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/power.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/clipboard.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/settings.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/connect.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/fullscreen.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /app/images/disconnect.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/input/util.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/util/int.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/util/strings.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/util/element.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/util/eventtarget.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/display.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/inflator.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/deflator.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/input/gesturehandler.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/util/cursor.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/websock.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/des.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/input/xtscancodes.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/encodings.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/decoders/raw.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/decoders/copyrect.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/decoders/rre.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/decoders/tight.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/decoders/hextile.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/decoders/tightpng.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/input/vkeys.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/input/fixedkeys.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/input/domkeytable.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/zlib/inflate.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/zlib/zstream.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /core/base64.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/zlib/deflate.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/utils/common.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/zlib/adler32.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/zlib/crc32.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/zlib/inffast.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/zlib/inftrees.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/zlib/trees.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /vendor/pako/lib/zlib/messages.js HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:22] "GET /package.json HTTP/1.1" 200 -
2.2.2.2: new handler Process
Resolving token 'TKNXXXXXXXXXXXXXXXX'
response from redis : 4.4.4.4:5901
host: 4.4.4.4, port: 5901
2.2.2.2 - - [16/May/2022 17:01:22] "GET /websockify?token=TKNXXXXXXXXXXX HTTP/1.1" 101 -
2.2.2.2 - - [16/May/2022 17:01:22] 2.2.2.2: SSL/TLS (wss://) WebSocket connection
2.2.2.2 - - [16/May/2022 17:01:22] 2.2.2.2: Path: '/websockify?token=TKNXXXXXXXXXXX'
2.2.2.2 - - [16/May/2022 17:01:22] connecting to: 4.4.4.4:5901
2.2.2.2 - - [16/May/2022 17:01:23] "GET /app/images/icons/novnc-192x192.png HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:23] "GET /app/images/icons/novnc-16x16.png HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:23] "GET /app/images/handle_bg.svg HTTP/1.1" 200 -
2.2.2.2 - - [16/May/2022 17:01:23] "GET /app/images/handle.svg HTTP/1.1" 200 -

javicacheiro avatar May 16 '22 15:05 javicacheiro

Sorry, I forgot to include in the previous comment the output we would get without the "--verbose" option:

TokenRedis backend initilized (3.3.3.3:6379)
WebSocket server settings:
  - Listen on 1.1.1.1:9444
  - Web server. Web root: /root/websockify/standalone/novnc/noVNC-1.3.0
  - SSL/TLS support
  - Deny non-SSL/TLS connections
  - proxying from 1.1.1.1:9444 to targets generated by TokenRedis
Resolving token 'TKNXXXX'
2.2.2.2 - - [16/May/2022 17:40:52] 2.2.2.2: SSL/TLS (wss://) WebSocket connection
2.2.2.2 - - [16/May/2022 17:40:52] 2.2.2.2: Path: '/websockify?token=TKNXXXX'
2.2.2.2 - - [16/May/2022 17:40:52] connecting to: 4.4.4.4:5901

javicacheiro avatar May 16 '22 15:05 javicacheiro