use logging module instead of writes to stderr

2 files changed, 157 insertions, 40 deletions

diff --git a/pyserial/examples/rfc2217_server.py b/pyserial/examples/rfc2217_server.py
index 0faee95..d5ea771 100644
--- a/pyserial/examples/rfc2217_server.py
+++ b/pyserial/examples/rfc2217_server.py
@@ -12,18 +12,26 @@ import time
 import socket
 import serial
 import serial.rfc2217
+import logging
 
 class Redirector:
-    def __init__(self, serial_instance, socket):
+    def __init__(self, serial_instance, socket, debug=None):
         self.serial = serial_instance
         self.socket = socket
         self._write_lock = threading.Lock()
-        self.rfc2217 = serial.rfc2217.PortManager(self.serial, self, debug_output=False)
+        self.rfc2217 = serial.rfc2217.PortManager(
+            self.serial,
+            self,
+            debug_output = (debug and logging.getLogger('rfc2217.server'))
+            )
+        self.log = logging.getLogger('redirector')
 
     def statusline_poller(self):
+        self.log.debug('status line poll thread started')
         while self.alive:
             time.sleep(1)
             self.rfc2217.check_modem_lines()
+        self.log.debug('status line poll thread terminated')
 
     def shortcut(self):
         """connect the serial port to the TCP port by copying everything
@@ -41,6 +49,7 @@ class Redirector:
 
     def reader(self):
         """loop forever and copy serial->socket"""
+        self.log.debug('reader thread started')
         while self.alive:
             try:
                 data = self.serial.read(1)              # read one, blocking
@@ -56,10 +65,11 @@ class Redirector:
                     finally:
                         self._write_lock.release()
             except socket.error, msg:
-                sys.stderr.write('ERROR: %s\n' % msg)
+                self.log.error('%s' % (msg,))
                 # probably got disconnected
                 break
         self.alive = False
+        self.log.debug('reader thread terminated')
 
     def write(self, data):
         """thread safe socket write with no data escaping. used to send telnet stuff"""
@@ -78,13 +88,14 @@ class Redirector:
                     break
                 self.serial.write(serial.to_bytes(self.rfc2217.filter(data)))
             except socket.error, msg:
-                sys.stderr.write('ERROR: %s\n' % msg)
+                self.log.error('%s' % (msg,))
                 # probably got disconnected
                 break
         self.stop()
 
     def stop(self):
         """Stop copying"""
+        self.log.debug('stopping')
         if self.alive:
             self.alive = False
             self.thread_read.join()
@@ -113,25 +124,43 @@ it waits for the next connect.
         default = 2217
     )
 
+    parser.add_option("-v", "--verbose",
+        dest = "verbosity",
+        action = "count",
+        help = "print more diagnostic messages (option can be given multiple times)",
+        default = 0
+    )
+
     (options, args) = parser.parse_args()
 
     if len(args) != 1:
         parser.error('serial port name required as argument')
 
+    if options.verbosity > 3:
+        options.verbosity = 3
+    level = (
+        logging.WARNING,
+        logging.INFO,
+        logging.DEBUG,
+        logging.NOTSET,
+        )[options.verbosity]
+    logging.basicConfig(level=logging.INFO)
+    logging.getLogger('rfc2217').setLevel(level)
+
     # connect to serial port
     ser = serial.Serial()
     ser.port     = args[0]
     ser.timeout  = 3     # required so that the reader thread can exit
 
-    sys.stderr.write("--- RFC 2217 TCP/IP to Serial redirector --- type Ctrl-C / BREAK to quit\n")
+    logging.info("RFC 2217 TCP/IP to Serial redirector - type Ctrl-C / BREAK to quit")
 
     try:
         ser.open()
     except serial.SerialException, e:
-        sys.stderr.write("Could not open serial port %s: %s\n" % (ser.portstr, e))
+        logging.error("Could not open serial port %s: %s" % (ser.portstr, e))
         sys.exit(1)
 
-    sys.stderr.write("--- Serving serial port: %s\n" % (ser.portstr,))
+    logging.info("Serving serial port: %s" % (ser.portstr,))
     settings = ser.getSettingsDict()
     # reset contol line as no _remote_ "terminal" has been connected yet
     ser.setDTR(False)
@@ -141,11 +170,11 @@ it waits for the next connect.
     srv.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
     srv.bind( ('', options.local_port) )
     srv.listen(1)
-    sys.stderr.write("--- TCP/IP port: %s\n" % (options.local_port,))
+    logging.info("TCP/IP port: %s" % (options.local_port,))
     while True:
         try:
             connection, addr = srv.accept()
-            sys.stderr.write('Connected by %s:%s \n' % (addr[0], addr[1]))
+            logging.info('Connected by %s:%s' % (addr[0], addr[1]))
             connection.setsockopt( socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
             ser.setRTS(True)
             ser.setDTR(True)
@@ -153,11 +182,12 @@ it waits for the next connect.
             r = Redirector(
                 ser,
                 connection,
+                options.verbosity > 0
             )
             try:
                 r.shortcut()
             finally:
-                sys.stderr.write('Disconnected\n')
+                logging.info('Disconnected')
                 r.stop()
                 connection.close()
                 ser.setDTR(False)
@@ -168,6 +198,6 @@ it waits for the next connect.
         except KeyboardInterrupt:
             break
         except socket.error, msg:
-            sys.stderr.write('ERROR: %s\n' % msg)
+            logging.error('%s' % (msg,))
 
-    sys.stderr.write('\n--- exit ---\n')
+    logging.info('--- exit ---')
diff --git a/pyserial/serial/rfc2217.py b/pyserial/serial/rfc2217.py
index 20efc43..5ad839c 100644
--- a/pyserial/serial/rfc2217.py
+++ b/pyserial/serial/rfc2217.py
@@ -65,12 +65,22 @@ import struct
 import socket
 import threading
 import Queue
+import logging
 
 # port string is expected to be something like this:
 # rfc2217://host:port
 # host may be an IP or including domain, whatever.
 # port is 0...65535
 
+LOGGER_LEVELS = {
+    'debug': logging.DEBUG,
+    'info': logging.INFO,
+    'warning': logging.WARNING,
+    'error': logging.ERROR,
+    'critical': logging.CRITICAL
+    }
+
+
 # telnet protocol characters
 IAC  = to_bytes([255]) # Interpret As Command
 DONT = to_bytes([254])
@@ -303,7 +313,7 @@ class TelnetSubnegotiation(object):
         self.state = REQUESTED
         self.connection.rfc2217SendSubnegotiation(self.option, self.value)
         if self.connection.debug_output:
-            print "SB Requesting %s -> %r" % (self.name, self.value)
+            self.connection.debug_output.debug("SB Requesting %s -> %r" % (self.name, self.value))
 
     def isReady(self):
         """check if answer from server has been received. when server rejects
@@ -335,7 +345,7 @@ class TelnetSubnegotiation(object):
             # error propagation done in isReady
             self.state = REALLY_INACTIVE
         if self.connection.debug_output:
-            print "SB Answer %s -> %r -> %s" % (self.name, suboption, self.state)
+            self.connection.debug_output.debug("SB Answer %s -> %r -> %s" % (self.name, suboption, self.state))
 
 
 class RFC2217Serial(SerialBase):
@@ -347,7 +357,7 @@ class RFC2217Serial(SerialBase):
     def open(self):
         """Open port with current settings. This may throw a SerialException
            if the port cannot be opened."""
-        self.debug_output = False
+        self.debug_output = None
         self._ignore_set_control_answer = False
         self._poll_modem_state = False
         self._network_timeout = 3
@@ -406,7 +416,7 @@ class RFC2217Serial(SerialBase):
 
         self._thread = threading.Thread(target=self._telnetReadLoop)
         self._thread.setDaemon(True)
-        self._thread.setName('pySerial RFC2217 reader thread for %s' % (self._port,))
+        self._thread.setName('pySerial RFC 2217 reader thread for %s' % (self._port,))
         self._thread.start()
 
         # negotiate Telnet/RFC 2217 -> send initial requests
@@ -422,7 +432,7 @@ class RFC2217Serial(SerialBase):
         else:
             raise SerialException("Remote does not seem to support RFC2217 or BINARY mode %r" % mandadory_options)
         if self.debug_output:
-            print self._telnet_options
+            self.debug_output.info("Negotiated options: %s" % self._telnet_options)
 
         # fine, go on, set RFC 2271 specific things
         self._reconfigurePort()
@@ -457,6 +467,8 @@ class RFC2217Serial(SerialBase):
 
         # and now wait until parameters are active
         items = self._rfc2217_port_settings.values()
+        if self.debug_output:
+            self.debug_output.debug("Negotiating settings: %s" % (items,))
         timeout_time = time.time() + self._network_timeout
         while time.time() < timeout_time:
             time.sleep(0.05)    # prevent 100% CPU load
@@ -465,8 +477,7 @@ class RFC2217Serial(SerialBase):
         else:
             raise SerialException("Remote does not accept parameter change (RFC2217): %r" % items)
         if self.debug_output:
-            print items
-
+            self.debug_output.info("Negotiated settings: %s" % (items,))
 
         if self._rtscts and self._xonxoff:
             raise ValueError('xonxoff and rtscts together are not supported')
@@ -511,8 +522,11 @@ class RFC2217Serial(SerialBase):
                         option, value = option.split('=', 1)
                     else:
                         value = None
-                    if option == 'debug':
-                        self.debug_output = True
+                    if option == 'logging':
+                        logging.basicConfig()   # XXX is that good to call it here?
+                        self.debug_output = logging.getLogger('rfc2217.client')
+                        self.debug_output.setLevel(LOGGER_LEVELS[value])
+                        self.debug_output.debug('enabled logging')
                     elif option == 'ign_set_control':
                         self._ignore_set_control_answer = True
                     elif option == 'poll_modem':
@@ -592,6 +606,8 @@ class RFC2217Serial(SerialBase):
         """Set break: Controls TXD. When active, to transmitting is
         possible."""
         if not self._isOpen: raise portNotOpenError
+        if self.debug_output:
+            self.debug_output.info('set BREAK to %s' % ('inactive', 'active')[bool(level)])
         if level:
             self.rfc2217SetControl(SET_CONTROL_BREAK_ON)
         else:
@@ -600,6 +616,8 @@ class RFC2217Serial(SerialBase):
     def setRTS(self, level=True):
         """Set terminal status line: Request To Send."""
         if not self._isOpen: raise portNotOpenError
+        if self.debug_output:
+            self.debug_output.info('set RTS to %s' % ('inactive', 'active')[bool(level)])
         if level:
             self.rfc2217SetControl(SET_CONTROL_RTS_ON)
         else:
@@ -608,6 +626,8 @@ class RFC2217Serial(SerialBase):
     def setDTR(self, level=True):
         """Set terminal status line: Data Terminal Ready."""
         if not self._isOpen: raise portNotOpenError
+        if self.debug_output:
+            self.debug_output.info('set DTR to %s' % ('inactive', 'active')[bool(level)])
         if level:
             self.rfc2217SetControl(SET_CONTROL_DTR_ON)
         else:
@@ -694,14 +714,15 @@ class RFC2217Serial(SerialBase):
         finally:
             self._thread = None
             if self.debug_output:
-                print "read thread terminated"
+                self.debug_output.debug("read thread terminated")
 
     # - incoming telnet commands and options
 
     def _telnetProcessCommand(self, command):
         """Process commands other than DO, DONT, WILL, WONT."""
         # Currently none. RFC2217 only uses negotiation and subnegotiation.
-        #~ print "_telnetProcessCommand %r" % ord(command)
+        if self.debug_output:
+            self.debug_output.warning("ignoring Telnet command: %r" % (command,))
 
     def _telnetNegotiateOption(self, command, option):
         """Process incoming DO, DONT, WILL, WONT."""
@@ -719,6 +740,8 @@ class RFC2217Serial(SerialBase):
             # only answer to positive requests and deny them
             if command == WILL or command == DO:
                 self.telnetSendOption((command == WILL and DONT or WONT), option)
+                if self.debug_output:
+                    self.debug_output.warning("rejected Telnet option: %r" % (option,))
 
 
     def _telnetProcessSubnegotiation(self, suboption):
@@ -727,11 +750,11 @@ class RFC2217Serial(SerialBase):
             if suboption[1:2] == SERVER_NOTIFY_LINESTATE and len(suboption) >= 3:
                 self._linestate = ord(suboption[2:3]) # ensure it is a number
                 if self.debug_output:
-                    print "NOTIFY_LINESTATE: %s" % self._linestate
+                    self.debug_output.info("NOTIFY_LINESTATE: %s" % self._linestate)
             elif suboption[1:2] == SERVER_NOTIFY_MODEMSTATE and len(suboption) >= 3:
                 self._modemstate = ord(suboption[2:3]) # ensure it is a number
                 if self.debug_output:
-                    print "NOTIFY_MODEMSTATE: %s" % self._modemstate
+                    self.debug_output.info("NOTIFY_MODEMSTATE: %s" % self._modemstate)
                 # update time when we think that a poll would make sense
                 self._modemstate_expires = time.time() + 0.3
             elif suboption[1:2] == FLOWCONTROL_SUSPEND:
@@ -746,11 +769,10 @@ class RFC2217Serial(SerialBase):
                         break
                 else:
                     if self.debug_output:
-                        print "ignoring COM_PORT_OPTION: %r" % list(suboption[1:])
-                #~ print "_telnetProcessSubnegotiation COM_PORT_OPTION %r" % suboption[1:]
+                        self.debug_output.warning("ignoring COM_PORT_OPTION: %r" % (suboption,))
         else:
-            pass
-            #~ print "_telnetProcessSubnegotiation unknown %r" % suboption
+            if self.debug_output:
+                self.debug_output.warning("ignoring subnegotiation: %r" % (suboption,))
 
     # - outgoing telnet commands and options
 
@@ -799,6 +821,8 @@ class RFC2217Serial(SerialBase):
         etc.)"""
         # active modem state polling enabled? is the value fresh enough?
         if self._poll_modem_state and self._modemstate_expires < time.time():
+            if self.debug_output:
+                self.debug_output.debug('polling modem state')
             # when it is older, request an update
             self.rfc2217SendSubnegotiation(NOTIFY_MODEMSTATE)
             timeout_time = time.time() + self._network_timeout
@@ -807,17 +831,22 @@ class RFC2217Serial(SerialBase):
                 # when expiration time is updated, it means that there is a new
                 # value
                 if self._modemstate_expires > time.time():
+                    if self.debug_output:
+                        self.debug_output.warning('poll for modem state failed')
                     break
             # even when there is a timeout, do not generate an error just
             # return the last known value. this way we can support buggy
             # servers that do not respond to polls, but send automatic
             # updates.
         if self._modemstate is not None:
+            if self.debug_output:
+                self.debug_output.debug('using cached modem state')
             return self._modemstate
         else:
             # never received a notification from the server
             raise SerialException("remote sends no NOTIFY_MODEMSTATE")
 
+
 # assemble Serial class with the platform specific implementation and the base
 # for file-like behavior. for Python 2.6 and newer, that provide the new I/O
 # library, derive from io.RawIOBase
@@ -834,14 +863,14 @@ else:
 
 
 #############################################################################
-# The following is code that helps implementing an RFC2217 server.
+# The following is code that helps implementing an RFC 2217 server.
 
 class PortManager(object):
     """This class manages the state of Telnet and RFC 2217. It needs a serial
     instance and a connection to work with. connection is expected to implement
     a (thread safe) write function, that writes the string to the network."""
 
-    def __init__(self, serial_port, connection, debug_output=False):
+    def __init__(self, serial_port, connection, debug_output=None):
         self.serial = serial_port
         self.connection = connection
         self.debug_output = debug_output
@@ -869,6 +898,8 @@ class PortManager(object):
             ]
 
         # negotiate Telnet/RFC2217 -> send initial requests
+        if self.debug_output:
+            self.debug_output.debug("requesting initial Telnet/RFC 2217 options")
         for option in self._telnet_options:
             if option.state is REQUESTED:
                 self.telnetSendOption(option.send_yes, option.option)
@@ -884,6 +915,8 @@ class PortManager(object):
         # and i guess there are incorrect clients too.. so be happy if client
         # answers one or the other positively.
         self._client_is_rfc2217 = True
+        if self.debug_output:
+            self.debug_output.info("client accepts RFC 2217")
         # this is to ensure that the client gets a notification, even if there
         # was no change
         self.check_modem_lines(force_notification=True)
@@ -927,7 +960,7 @@ class PortManager(object):
                     to_bytes([modemstate & self.modemstate_mask])
                     )
                 if self.debug_output:
-                    print "NOTIFY_MODEMSTATE: %s" % (modemstate,)
+                    self.debug_output.info("NOTIFY_MODEMSTATE: %s" % (modemstate,))
             # save last state, but forget about deltas.
             # otherwise it would also notify about changing deltas which is
             # probably not very useful
@@ -1032,14 +1065,19 @@ class PortManager(object):
     def _telnetProcessSubnegotiation(self, suboption):
         """Process subnegotiation, the data between IAC SB and IAC SE."""
         if suboption[0:1] == COM_PORT_OPTION:
+            if self.debug_output:
+                self.debug_output.debug('recevied COM_PORT_OPTION: %r' % (suboption,))
             if suboption[1:2] == SET_BAUDRATE:
                 backup = self.serial.baudrate
                 try:
                     (self.serial.baudrate,) = struct.unpack("!I", suboption[2:6])
                 except ValueError, e:
                     if self.debug_output:
-                        print "failed to set baudrate: %s" % (e,)
+                        self.debug_output.error("failed to set baud rate: %s" % (e,))
                     self.serial.baudrate = backup
+                else:
+                    if self.debug_output:
+                        self.debug_output.info("changed baud rate: %s" % (self.serial.baudrate,))
                 self.rfc2217SendSubnegotiation(SERVER_SET_BAUDRATE, struct.pack("!I", self.serial.baudrate))
             elif suboption[1:2] == SET_DATASIZE:
                 backup = self.serial.bytesize
@@ -1047,8 +1085,11 @@ class PortManager(object):
                     (self.serial.bytesize,) = struct.unpack("!B", suboption[2:3])
                 except ValueError, e:
                     if self.debug_output:
-                        print "failed to set datasize: %s" % (e,)
+                        self.debug_output.error("failed to set data size: %s" % (e,))
                     self.serial.bytesize = backup
+                else:
+                    if self.debug_output:
+                        self.debug_output.info("changed data size: %s" % (self.serial.bytesize,))
                 self.rfc2217SendSubnegotiation(SERVER_SET_DATASIZE, struct.pack("!B", self.serial.bytesize))
             elif suboption[1:2] == SET_PARITY:
                 backup = self.serial.parity
@@ -1056,8 +1097,11 @@ class PortManager(object):
                     self.serial.parity = RFC2217_REVERSE_PARITY_MAP[struct.unpack("!B", suboption[2:3])[0]]
                 except ValueError, e:
                     if self.debug_output:
-                        print "failed to set parity: %s" % (e,)
+                        self.debug_output.error("failed to set parity: %s" % (e,))
                     self.serial.parity = backup
+                else:
+                    if self.debug_output:
+                        self.debug_output.info("changed parity: %s" % (self.serial.parity,))
                 self.rfc2217SendSubnegotiation(
                     SERVER_SET_PARITY,
                     struct.pack("!B", RFC2217_PARITY_MAP[self.serial.parity])
@@ -1068,8 +1112,11 @@ class PortManager(object):
                     self.serial.stopbits = RFC2217_REVERSE_STOPBIT_MAP[struct.unpack("!B", suboption[2:3])[0]]
                 except ValueError, e:
                     if self.debug_output:
-                        print "failed to set stopsize: %s" % (e,)
+                        self.debug_output.error("failed to set stopsize: %s" % (e,))
                     self.serial.stopbits = backup
+                else:
+                    if self.debug_output:
+                        self.debug_output.info("changed stop bits: %s" % (self.serial.stopbits,))
                 self.rfc2217SendSubnegotiation(
                     SERVER_SET_STOPSIZE,
                     struct.pack("!B", RFC2217_STOPBIT_MAP[self.serial.stopbits])
@@ -1085,37 +1132,61 @@ class PortManager(object):
                 elif suboption[2:3] == SET_CONTROL_USE_NO_FLOW_CONTROL:
                     self.serial.xonxoff = False
                     self.serial.rtscts = False
+                    if self.debug_output:
+                        self.debug_output.info("changed flow control to None")
                     self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_USE_NO_FLOW_CONTROL)
                 elif suboption[2:3] == SET_CONTROL_USE_SW_FLOW_CONTROL:
                     self.serial.xonxoff = True
+                    if self.debug_output:
+                        self.debug_output.info("changed flow control to XON/XOFF")
                     self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_USE_SW_FLOW_CONTROL)
                 elif suboption[2:3] == SET_CONTROL_USE_HW_FLOW_CONTROL:
                     self.serial.rtscts = True
+                    if self.debug_output:
+                        self.debug_output.info("changed flow control to RTS/CTS")
                     self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_USE_HW_FLOW_CONTROL)
                 elif suboption[2:3] == SET_CONTROL_REQ_BREAK_STATE:
+                    if self.debug_output:
+                        self.debug_output.warning("requested break state - not implemented")
                     pass # XXX needs cached value
                 elif suboption[2:3] == SET_CONTROL_BREAK_ON:
                     self.serial.setBreak(True)
+                    if self.debug_output:
+                        self.debug_output.info("changed BREAK to active")
                     self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_BREAK_ON)
                 elif suboption[2:3] == SET_CONTROL_BREAK_OFF:
                     self.serial.setBreak(False)
+                    if self.debug_output:
+                        self.debug_output.info("changed BREAK to inactive")
                     self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_BREAK_OFF)
                 elif suboption[2:3] == SET_CONTROL_REQ_DTR:
+                    if self.debug_output:
+                        self.debug_output.warning("requested DTR state - not implemented")
                     pass # XXX needs cached value
                 elif suboption[2:3] == SET_CONTROL_DTR_ON:
                     self.serial.setDTR(True)
+                    if self.debug_output:
+                        self.debug_output.info("changed DTR to active")
                     self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_DTR_ON)
                 elif suboption[2:3] == SET_CONTROL_DTR_OFF:
                     self.serial.setDTR(False)
+                    if self.debug_output:
+                        self.debug_output.info("changed DTR to inactive")
                     self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_DTR_OFF)
                 elif suboption[2:3] == SET_CONTROL_REQ_RTS:
+                    if self.debug_output:
+                        self.debug_output.warning("requested RTS state - not implemented")
                     pass # XXX needs cached value
                     #~ self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_RTS_ON)
                 elif suboption[2:3] == SET_CONTROL_RTS_ON:
                     self.serial.setRTS(True)
+                    if self.debug_output:
+                        self.debug_output.info("changed RTS to active")
                     self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_RTS_ON)
                 elif suboption[2:3] == SET_CONTROL_RTS_OFF:
                     self.serial.setRTS(False)
+                    if self.debug_output:
+                        self.debug_output.info("changed RTS to inactive")
                     self.rfc2217SendSubnegotiation(SERVER_SET_CONTROL, SET_CONTROL_RTS_OFF)
                 #~ elif suboption[2:3] == SET_CONTROL_REQ_FLOW_SETTING_IN:
                 #~ elif suboption[2:3] == SET_CONTROL_USE_NO_FLOW_CONTROL_IN:
@@ -1131,36 +1202,52 @@ class PortManager(object):
                     to_bytes([0])   # sorry, nothing like that imeplemented
                     )
             elif suboption[1:2] == NOTIFY_MODEMSTATE:
+                if self.debug_output:
+                    self.debug_output.info("request for modem state")
                 # client polls for current state
                 self.check_modem_lines(force_notification=True)
             elif suboption[1:2] == FLOWCONTROL_SUSPEND:
+                if self.debug_output:
+                    self.debug_output.info("suspend")
                 self._remote_suspend_flow = True
             elif suboption[1:2] == FLOWCONTROL_RESUME:
+                if self.debug_output:
+                    self.debug_output.info("resume")
                 self._remote_suspend_flow = False
             elif suboption[1:2] == SET_LINESTATE_MASK:
                 self.linstate_mask = ord(suboption[2:3]) # ensure it is a number
+                if self.debug_output:
+                    self.debug_output.info("line state mask: 0x%02" % (self.linstate_mask,))
             elif suboption[1:2] == SET_MODEMSTATE_MASK:
                 self.modemstate_mask = ord(suboption[2:3]) # ensure it is a number
+                if self.debug_output:
+                    self.debug_output.info("modem state mask: 0x%02" % (self.modemstate_mask,))
             elif suboption[1:2] == PURGE_DATA:
                 if suboption[2:3] == PURGE_RECEIVE_BUFFER:
                     self.serial.flushInput()
+                    if self.debug_output:
+                        self.debug_output.info("purge in")
                     self.rfc2217SendSubnegotiation(SERVER_PURGE_DATA, PURGE_RECEIVE_BUFFER)
                 elif suboption[2:3] == PURGE_TRANSMIT_BUFFER:
                     self.serial.flushOutput()
+                    if self.debug_output:
+                        self.debug_output.info("purge out")
                     self.rfc2217SendSubnegotiation(SERVER_PURGE_DATA, PURGE_TRANSMIT_BUFFER)
                 elif suboption[2:3] == PURGE_BOTH_BUFFERS:
                     self.serial.flushInput()
                     self.serial.flushOutput()
+                    if self.debug_output:
+                        self.debug_output.info("purge both")
                     self.rfc2217SendSubnegotiation(SERVER_PURGE_DATA, PURGE_BOTH_BUFFERS)
                 else:
                     if self.debug_output:
-                        print "undefined PURGE_DATA: %r" % list(suboption[2:])
+                        self.debug_output.error("undefined PURGE_DATA: %r" % list(suboption[2:]))
             else:
                 if self.debug_output:
-                    print "undefined COM_PORT_OPTION: %r" % list(suboption[1:])
+                    self.debug_output.error("undefined COM_PORT_OPTION: %r" % list(suboption[1:]))
         else:
-            pass
-            #~ print "_telnetProcessSubnegotiation unknown %r" % suboption
+            if self.debug_output:
+                self.debug_output.warning("unknown subnegotiation: %r" % (suboption,))
 
 
 # simple client test