websocket: use python logging module

WebSocketServer is a library module, as such, it cannot assume it can
write output to process stdout.

Python logging module is designed in order to allow subscribers to
handle the output out of modules. It is simple and generic mechanism to
separate between data producer and data handling.

Python logging API also has the nature of log level, so the verbose
parameter can probably be obsoleted in favor of logging level. And of
course the logging API has built in support for exception tracebacks, no
need for manual format.

The msg and vmsg were left for backward compatibility and to keep the
prefix of message, need to consider to drop these in favor of extra
parameter of python logging API.

Signed-off-by: Alon Bar-Lev <alon.barlev@gmail.com>
This commit is contained in:
Alon Bar-Lev 2013-06-01 01:08:36 +03:00
parent 7084f43688
commit 095b752c8e
2 changed files with 62 additions and 38 deletions

View File

@ -16,7 +16,7 @@ as taken from http://docs.python.org/dev/library/ssl.html#certificates
'''
import os, sys, time, errno, signal, socket, traceback, select
import os, sys, time, errno, signal, socket, select, logging
import array, struct
from base64 import b64encode, b64decode
@ -70,6 +70,8 @@ class WebSocketServer(object):
Must be sub-classed with new_client method definition.
"""
log_prefix = "novnc"
buffer_size = 65536
@ -121,6 +123,8 @@ Sec-WebSocket-Accept: %s\r
self.ws_connection = False
self.handler_id = 1
self.logger = self.get_logger()
# Make paths settings absolute
self.cert = os.path.abspath(cert)
self.key = self.web = self.record = ''
@ -141,30 +145,35 @@ Sec-WebSocket-Accept: %s\r
raise Exception("Module 'resource' required to daemonize")
# Show configuration
print("WebSocket server settings:")
print(" - Listen on %s:%s" % (
self.listen_host, self.listen_port))
print(" - Flash security policy server")
self.logger.info("WebSocket server settings:")
self.logger.info(" - Listen on %s:%s",
self.listen_host, self.listen_port)
self.logger.info(" - Flash security policy server")
if self.web:
print(" - Web server. Web root: %s" % self.web)
self.logger.info(" - Web server. Web root: %s", self.web)
if ssl:
if os.path.exists(self.cert):
print(" - SSL/TLS support")
self.logger.info(" - SSL/TLS support")
if self.ssl_only:
print(" - Deny non-SSL/TLS connections")
self.logger.info(" - Deny non-SSL/TLS connections")
else:
print(" - No SSL/TLS support (no cert file)")
self.logger.info(" - No SSL/TLS support (no cert file)")
else:
print(" - No SSL/TLS support (no 'ssl' module)")
self.logger.info(" - No SSL/TLS support (no 'ssl' module)")
if self.daemon:
print(" - Backgrounding (daemon)")
self.logger.info(" - Backgrounding (daemon)")
if self.record:
print(" - Recording to '%s.*'" % self.record)
self.logger.info(" - Recording to '%s.*'", self.record)
#
# WebSocketServer static methods
#
@staticmethod
def get_logger():
return logging.getLogger("%s.%s" % (
WebSocketServer.log_prefix, WebSocketServer.__class__.__name__))
@staticmethod
def socket(host, port=None, connect=False, prefer_ipv6=False, unix_socket=None, use_ssl=False):
""" Resolve a host (and optional port) to an IPv4 or IPv6
@ -326,6 +335,8 @@ Sec-WebSocket-Accept: %s\r
'close_code' : 1000,
'close_reason' : ''}
logger = WebSocketServer.get_logger()
blen = len(buf)
f['left'] = blen
@ -364,15 +375,16 @@ Sec-WebSocket-Accept: %s\r
f['payload'] = WebSocketServer.unmask(buf, f['hlen'],
f['length'])
else:
print("Unmasked frame: %s" % repr(buf))
logger.debug("Unmasked frame: %s", repr(buf))
f['payload'] = buf[(f['hlen'] + f['masked'] * 4):full_len]
if base64 and f['opcode'] in [1, 2]:
try:
f['payload'] = b64decode(f['payload'])
except:
print("Exception while b64decoding buffer: %s" %
logger.warning("Exception while b64decoding buffer: %s",
repr(buf))
logger.debug('Exception', exc_info=True)
raise
if f['opcode'] == 0x08:
@ -416,20 +428,20 @@ Sec-WebSocket-Accept: %s\r
#
def traffic(self, token="."):
""" Show traffic flow in verbose mode. """
if self.verbose and not self.daemon:
sys.stdout.write(token)
sys.stdout.flush()
""" Show traffic flow mode. """
self.logger.debug("%s", token)
def msg(self, msg):
def log(self, lvl, msg, *args, **kwargs):
self.logger.log(lvl, "% 3d: %s" % (self.handler_id, msg),
*args, **kwargs)
def msg(self, *args, **kwargs):
""" Output message with handler_id prefix. """
if not self.daemon:
print("% 3d: %s" % (self.handler_id, msg))
self.log(logging.INFO, *args, **kwargs)
def vmsg(self, msg):
""" Same as msg() but only if verbose. """
if self.verbose:
self.msg(msg)
def vmsg(self, *args, **kwargs):
""" Same as msg() but as debug. """
self.log(logging.DEBUG, *args, **kwargs)
#
# Main WebSocketServer methods
@ -817,8 +829,7 @@ Sec-WebSocket-Accept: %s\r
except Exception:
_, exc, _ = sys.exc_info()
self.msg("handler exception: %s" % str(exc))
if self.verbose:
self.msg(traceback.format_exc())
self.vmsg("exception", exc_info=True)
finally:
if self.rec:
self.rec.write("'EOF'];\n")
@ -951,17 +962,16 @@ Sec-WebSocket-Accept: %s\r
break
except Exception:
_, exc, _ = sys.exc_info()
self.msg("handler exception: %s" % str(exc))
if self.verbose:
self.msg(traceback.format_exc())
self.msg("handler exception: %s", str(exc))
self.vmsg("exception", exc_info=True)
finally:
if startsock:
startsock.close()
finally:
# Close listen port
self.vmsg("Closing socket listening at %s:%s"
% (self.listen_host, self.listen_port))
self.vmsg("Closing socket listening at %s:%s",
self.listen_host, self.listen_port)
lsock.close()
# Restore signals

View File

@ -11,7 +11,7 @@ as taken from http://docs.python.org/dev/library/ssl.html#certificates
'''
import signal, socket, optparse, time, os, sys, subprocess
import signal, socket, optparse, time, os, sys, subprocess, logging
from select import select
import websocket
try:
@ -86,7 +86,7 @@ Traffic Legend:
websocket.WebSocketServer.__init__(self, *args, **kwargs)
def run_wrap_cmd(self):
print("Starting '%s'" % " ".join(self.wrap_cmd))
self.logger.info("Starting '%s'", " ".join(self.wrap_cmd))
self.wrap_times.append(time.time())
self.wrap_times.pop(0)
self.cmd = subprocess.Popen(
@ -116,7 +116,7 @@ Traffic Legend:
if self.ssl_target:
msg += " (using SSL)"
print(msg + "\n")
self.logger.info(msg)
if self.wrap_cmd:
self.run_wrap_cmd()
@ -142,7 +142,7 @@ Traffic Legend:
if (now - avg) < 10:
# 3 times in the last 10 seconds
if self.spawn_message:
print("Command respawning too fast")
self.logger.warning("Command respawning too fast")
self.spawn_message = False
else:
self.run_wrap_cmd()
@ -182,8 +182,7 @@ Traffic Legend:
tsock = self.socket(self.target_host, self.target_port,
connect=True, use_ssl=self.ssl_target, unix_socket=self.unix_target)
if self.verbose and not self.daemon:
print(self.traffic_legend)
self.logger.debug(self.traffic_legend)
# Start proxying
try:
@ -301,7 +300,19 @@ def _subprocess_setup():
signal.signal(signal.SIGPIPE, signal.SIG_DFL)
def logger_init():
logger = logging.getLogger(WebSocketProxy.log_prefix)
logger.propagate = False
logger.setLevel(logging.INFO)
h = logging.StreamHandler()
h.setLevel(logging.DEBUG)
h.setFormatter(logging.Formatter("%(levelname)-7s %(message)s"))
logger.addHandler(h)
def websockify_init():
logger_init()
usage = "\n %prog [options]"
usage += " [source_addr:]source_port [target_addr:target_port]"
usage += "\n %prog [options]"
@ -347,6 +358,9 @@ def websockify_init():
"directory containing configuration files of this form")
(opts, args) = parser.parse_args()
if opts.verbose:
logging.getLogger(WebSocketProxy.log_prefix).setLevel(logging.DEBUG)
# Sanity checks
if len(args) < 2 and not (opts.target_cfg or opts.unix_target):
parser.error("Too few arguments")