Logging original client behind reverse proxy

[praimmugen]

Hi,
I'm running websockify behind Apache configured as reverse proxy. websockify listens on the loopback interface and connects to the VNC servers using a custom token plugin.

Everything works nicely but I'd like to get info regarding the original client in the logs of websockify for each relevant entry.

I made some changes to the request handler and to WebSockifyServer to accomodate this. I'm sharing them in case anybody is interested (using websockify behind a reverse proxy seems to be quite common), and I would greatly appreciate some feedback.

The change to the request handler is quite straightforward (just get the info from the X-Forwarded-For header, if present).

I also wanted to show this in the logs produced by WebSockifyServer, for example when no token is found. When this happens an exception gets raised from the request handler, so I added the information to the exception for WebSockifyServer to read. It works but I don't particularly like it, can anybody think of a better way to do it?

Thanks!

The log messages are like the following, when communication is proxied:

192.168.0.109 (forwarded by 127.0.0.1) - - [08/Mar/2018 17:38:59] "GET /?token=tokenABC HTTP/1.1" 101 -

And here's the diff:

diff --git a/websockify/websocketserver.py b/websockify/websocketserver.py
index 6d4824a..ef525d9 100644
--- a/websockify/websocketserver.py
+++ b/websockify/websocketserver.py
@@ -35,6 +35,13 @@ class WebSocketRequestHandler(BaseHTTPRequestHandler):
     def __init__(self, request, client_address, server):
         BaseHTTPRequestHandler.__init__(self, request, client_address, server)
 
+    def original_client(self):
+        # Get the originating client if running behind reverse proxies.
+        # Defaults to BaseHTTPRequestHandler.address_string() if request
+        # is not proxied
+        fwd_list = self.headers.get("X-Forwarded-For", None)
+        return fwd_list.split(",")[0] if fwd_list else self.address_string()
+
     def handle_one_request(self):
         """Extended request handler
 
diff --git a/websockify/websockifyserver.py b/websockify/websockifyserver.py
index f6c067c..366556c 100644
--- a/websockify/websockifyserver.py
+++ b/websockify/websockifyserver.py
@@ -99,13 +99,19 @@ class WebSockifyRequestHandler(WebSocketRequestHandler, SimpleHTTPRequestHandler
 
         WebSocketRequestHandler.__init__(self, req, addr, server)
 
-    def log_message(self, format, *args):
-        self.logger.info("%s - - [%s] %s" % (self.address_string(), self.log_date_time_string(), format % args))
-
     #
     # WebSocketRequestHandler logging/output functions
     #
 
+    def log_message(self, format, *args):
+        self.logger.info("%s - - [%s] %s" % (self.print_original_client_ip(), self.log_date_time_string(), format % args))
+
+    def print_original_client_ip(self):
+        client = self.original_client()
+        if client != self.address_string():
+            return "{original_client} (forwarded by {last_proxy})".format(original_client=client, last_proxy=self.address_string())
+        return client
+
     def print_traffic(self, token="."):
         """ Show traffic flow mode. """
         if self.traffic:
@@ -212,7 +218,13 @@ class WebSockifyRequestHandler(WebSocketRequestHandler, SimpleHTTPRequestHandler
 
     def handle_upgrade(self):
         # ensure connection is authorized, and determine the target
-        self.validate_connection()
+        try:
+            self.validate_connection()
+        except Exception as e:
+            if self.original_client() != self.address_string():
+                # Add info on remote client and re-raise
+                e.orig_client = self.print_original_client_ip()
+            raise
 
         WebSocketRequestHandler.handle_upgrade(self)
 
@@ -602,18 +614,20 @@ class WebSockifyServer(object):
     # WebSockifyServer logging/output functions
     #
 
-    def msg(self, *args, **kwargs):
+    def msg(self, msg, *args, **kwargs):
         """ Output message as info """
-        self.logger.log(logging.INFO, *args, **kwargs)
+        self.logger.log(logging.INFO, self.prefix_msg(msg, kwargs.pop("prefix_msg", None)), *args, **kwargs)
 
-    def vmsg(self, *args, **kwargs):
+    def vmsg(self, msg, *args, **kwargs):
         """ Same as msg() but as debug. """
-        self.logger.log(logging.DEBUG, *args, **kwargs)
+        self.logger.log(logging.DEBUG, self.prefix_msg(msg, kwargs.pop("prefix_msg", None)), *args, **kwargs)
 
-    def warn(self, *args, **kwargs):
+    def warn(self, msg, *args, **kwargs):
         """ Same as msg() but as warning. """
-        self.logger.log(logging.WARN, *args, **kwargs)
+        self.logger.log(logging.WARN, self.prefix_msg(msg, kwargs.pop("prefix_msg", None)), *args, **kwargs)
 
+    def prefix_msg(self, msg, prefix=None):
+        return "%s - %s" % (prefix, msg) if prefix else msg
 
     #
     # Events that can/should be overridden in sub-classes
@@ -666,17 +680,25 @@ class WebSockifyServer(object):
         try:
             try:
                 client = self.do_handshake(startsock, address)
-            except self.EClose:
-                _, exc, _ = sys.exc_info()
-                # Connection was not a WebSockets connection
-                if exc.args[0]:
-                    self.msg("%s: %s" % (address[0], exc.args[0]))
-            except WebSockifyServer.Terminate:
-                raise
-            except Exception:
-                _, exc, _ = sys.exc_info()
-                self.msg("handler exception: %s" % str(exc))
-                self.vmsg("exception", exc_info=True)
+            except Exception as e:
+                # Handle the generic exception first so that we get the original client once
+                try:
+                    original_client = e.orig_client
+                except AttributeError:
+                    original_client = None
+                try:
+                    raise
+                except self.EClose as e:
+                    _, exc, _ = sys.exc_info()
+                    # Connection was not a WebSockets connection
+                    if exc.args[0]:
+                        self.msg("%s: %s" % (address[0], exc.args[0]), prefix_msg=original_client)
+                except WebSockifyServer.Terminate:
+                    raise
+                except Exception:
+                    _, exc, _ = sys.exc_info()
+                    self.msg("original client: {} - handler exception: %s".format(original_client) % str(exc), prefix_msg=original_client)
+                    self.vmsg("exception", exc_info=True, prefix_msg=original_client)
         finally:
 
             if client and client != startsock:

[CendioOssman]

How does Apache log such things? The log format is based on Apache's format, so it would be best if we continue to follow that.

[praimmugen]

As far as I'm aware, there's no standard way of doing this on Apache. Since this is a special case consisting in running Apache behind a reverse proxy, it has been probably left to users to configure the log as they see fit by using the log formatting capability.

I think it would be nice get this info in the logs in websockify, but only in a way that doesn't add code for this special case where it doesn't belong (which is why I don't really like my change to get the info in WebSockifyServer too much). Also, as you suggest, a sensible formatting should be decided upon.

I found a few suggestions on how to configure the log format to get this info in, but as I said, none of them is in the Apache official docs.

For example, here's what's suggested on the AWS support site. Basically, they just added the whole X-Forwarded-For header in the log entry as first field, just before the host IP.

Here instead, the host field is replaced with X-Forwarded-For (only when such header exists).

Note that the X-Forwarded-For header is a comma-separated list of the original client + intermediate proxies. Somewhere else, others suggest ways to extract and log just the original client.

Also, this header is not standard, although it is widely used (by the mod_proxy Apache module, too). A standard header was proposed in RFC 7239 but it doesn't seem to be very widespread yet (for example, it hasn't been implemented in the Apache proxy module yet).

[CendioOssman]

We don't have the flexibility of Apache, so I'm a bit cautious about changing the log output. Maybe as a startup argument that replaces the host with the forwarded information.

[praimmugen]

Sorry for the late reply.

I followed your suggestion and added a startup option to enable this extra logging. I opened this pull request to discuss further.