Add debug logging for Telnet protocol negotiation

For improved debugging of Telnet protocol negotiations, add a log
function wrapper to the telnet module and apply it any time Telnet
commands are received or sent.

diff --git a/mudpy/telnet.py b/mudpy/telnet.py
index ed99faf..0cc29b8 100644 (file)
--- a/mudpy/telnet.py
+++ b/mudpy/telnet.py
@@ -10,11 +10,21 @@ import mudpy
 TELOPT_BINARY = 0  # transmit 8-bit data by the receiver (rfc 856)
 TELOPT_ECHO = 1  # echo received data back to the sender (rfc 857)
 TELOPT_SGA = 3  # suppress transmission of the go ahead character (rfc 858)
-# TELOPT_TTYPE = 24 # exchange terminal type information (rfc 1091)
+TELOPT_TTYPE = 24  # exchange terminal type information (rfc 1091)
 TELOPT_EOR = 25  # transmit end-of-record after transmitting data (rfc 885)
 TELOPT_NAWS = 31  # negotiate about window size (rfc 1073)
 TELOPT_LINEMODE = 34  # cooked line-by-line input mode (rfc 1184)
-
+option_names = {
+    TELOPT_BINARY: "8-bit binary",
+    TELOPT_ECHO: "echo",
+    TELOPT_SGA: "suppress go-ahead",
+    TELOPT_TTYPE: "terminal type",
+    TELOPT_EOR: "end of record",
+    TELOPT_NAWS: "negotiate about window size",
+    TELOPT_LINEMODE: "line mode",
+}
+
+# TODO(fungi): implement support for RFC 1091 terminal type information
 supported = (
     TELOPT_BINARY,
     TELOPT_ECHO,
@@ -34,6 +44,17 @@ WONT = 252  # refusal or confirmation of performing an option (rfc 854)
 DO = 253  # request or confirm performing an option (rfc 854)
 DONT = 254  # demand or confirm no longer performing an option (rfc 854)
 IAC = 255  # interpret as command escape character (rfc 854)
+command_names = {
+    EOR: "end of record",
+    SE: "subnegotiation end",
+    GA: "go ahead",
+    SB: "subnegotiation begin",
+    WILL: "will",
+    WONT: "won't",
+    DO: "do",
+    DONT: "don't",
+    IAC: "interpret as command",
+}
 
 # RFC 1143 option negotiation states
 NO = 0  # option is disabled
@@ -42,10 +63,31 @@ WANTNO = 2  # demanded disabling option
 WANTYES = 3  # requested enabling option
 WANTNO_OPPOSITE = 4  # demanded disabling option but queued an enable after it
 WANTYES_OPPOSITE = 5  # requested enabling option but queued a disable after it
+state_names = {
+    NO: "disabled",
+    YES: "enabled",
+    WANTNO: "demand disabling",
+    WANTYES: "request enabling",
+    WANTNO_OPPOSITE: "want no queued opposite",
+    WANTYES_OPPOSITE: "want yes queued opposite",
+}
 
 # RFC 1143 option negotiation parties
 HIM = 0
 US = 1
+party_names = {
+    HIM: "him",
+    US: "us",
+}
+
+
+def log(message, user):
+    """Log debugging info for Telnet client/server interactions."""
+    if user.account:
+        client = user.account.get("name", user)
+    else:
+        client = user
+    mudpy.misc.log('[telnet] %s %s.' % (message, client), 0)
 
 
 def telnet_proto(*arguments):
@@ -53,9 +95,15 @@ def telnet_proto(*arguments):
     return bytes((arguments))
 
 
+def translate_action(*command):
+    """Convert a Telnet command sequence into text suitable for logging."""
+    return "%s %s" % (command_names[command[0]], option_names[command[1]])
+
+
 def send_command(user, *command):
     """Sends a Telnet command string to the specified user's socket."""
     user.send(telnet_proto(IAC, *command), raw=True)
+    log('Sent "%s" to' % translate_action(*command), user)
 
 
 def is_enabled(user, telopt, party, state=YES):
@@ -132,12 +180,14 @@ def negotiate_telnet_options(user):
                     text.find(b"\r\n", position) > 0):
                 position += 1
                 text = text[:position] + text[position + 1:]
+                log('Escaped IAC from', user)
             else:
                 position += 2
 
         # implement an RFC 1143 option negotiation queue here
         elif len_text > position + 2 and WILL <= command <= DONT:
             telopt = text[position+2]
+            log('Received "%s" from' % translate_action(command, telopt), user)
             if telopt in supported:
                 if command <= WONT:
                     party = HIM
@@ -193,7 +243,7 @@ def negotiate_telnet_options(user):
 
         # otherwise, strip out a two-byte IAC command
         elif len_text > position + 2:
-            mudpy.misc.log("Unknown Telnet IAC command %s ignored." % command)
+            log("Ignored unknown command %s from" % command, user)
             text = text[:position] + text[position + 2:]
 
         # and this means we got the begining of an IAC

diff --git a/mudpy/tests/selftest.py b/mudpy/tests/selftest.py
index 179871e..3012c61 100644 (file)
--- a/mudpy/tests/selftest.py
+++ b/mudpy/tests/selftest.py
@@ -177,7 +177,7 @@ test_telnet_unknown = (
     # Send an unsupported negotiation command #127 which should get filtered
     # from the line of input
     (2, "> ", b"say glop\xff\x7fglyf\r\0"),
-    (2, r'Unknown Telnet IAC command 127 ignored\..*"Glopglyf\.".*> ', ""),
+    (2, r'Ignored unknown command 127 from admin\..*"Glopglyf\.".*> ', ""),
 )
 
 test_admin_restriction = (