Clean up logging and fix Python2/3 compatibility, EINTR handling

o Remove logging.basicConfig except in main path, and ensure that no
  imported modules invoke logging calls, to avoid logging complaining
  that there is no Null logger.
o Ensure that logging level extensions report calling function name
o Make web.py and pymodbus requirements-optional.txt, and only install
  them by default in Python2.
o Make cpppo.enip.server.main and cpppo.enip.server.client.main
  use argparse correctly, to get argv[1:] by default.
o Correctly implement log file rotation.
o Correctly test for EtherNet/IP CIP registers response.
o Correct handling of EINTR in cpppo.network.readable decorator
o Ship enip_server and enip_client as console_scripts in setup.py
o Version 1.9.6

GNUmakefile

@@ -33,7 +33,7 @@ PY3=python3
 #     LANG=en_CA.UTF-8
 #     LC_ALL=en_CA.UTF-8
 # 
-PYTESTOPTS=--capture=no
+PYTESTOPTS=-v # --capture=no
 PY2TEST=$(PY2) -m pytest $(PYTESTOPTS)
 PY3TEST=$(PY3) -m pytest $(PYTESTOPTS)
 

automata_test.py

@@ -16,12 +16,8 @@
 import sys
 import timeit
 
-# Allow relative imports when executing within package directory, for running tests
-sys.path.insert( 0, os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
-
 import cpppo
 
-logging.basicConfig( **cpppo.log_cfg )
 log				= logging.getLogger()
 log_not				= 0
 #log.setLevel( logging.INFO )

bin/modbus_sim.py

@@ -1,4 +1,7 @@
 #!/usr/bin/env python
+
+from __future__ import print_function
+
 '''
 modbus-sim.py -- A Modbus PLC Simulator, with various simulated failure modes
 
@@ -201,8 +204,8 @@ def registers_parse( txt ):
                                    else ( did, 10001 ) if reg >= 10001
                                    else ( cod,     1 ))
                 dct[reg - off] 	= val[reg - beg]
-        except Exception, e:
-            log.error( "Unrecognized registers '%s': %s" % ( txt, str( e )))
+        except Exception as exc:
+            log.error( "Unrecognized registers '%s': %s" % ( txt, str( exc )))
             raise
         log.info( "Holding Registers: %s" % ( repr.repr( hrd )))
         log.info( "Input   Registers: %s" % ( repr.repr( ird )))
@@ -316,7 +319,7 @@ def buildPacket(self, message):
                 func_code ) + data
 
             log.info("Returning corrupted package")
-        except Exception, e:
+        except Exception as exc:
             log.info("Could not build corrupt packet: %s" % ( traceback.format_exc() ))
         return packet
 
@@ -334,8 +337,8 @@ def StartTcpServerLogging( context=None, identity=None, framer=ModbusSocketFrame
     server = ModbusTcpServer(context, framer, identity, address)
     # Print the address successfully bound; this is useful, if attempts are made
     # to bind over a range of ports.
-    print "Success; Started Modbus/TCP Simulator; PID = %d; address = %s:%s" % (
-        os.getpid(), address[0] if address else "", address[1] if address else Defaults.Port )
+    print( "Success; Started Modbus/TCP Simulator; PID = %d; address = %s:%s" % (
+        os.getpid(), address[0] if address else "", address[1] if address else Defaults.Port ))
     sys.stdout.flush()
     server.serve_forever()
 
@@ -448,7 +451,7 @@ def main():
             StartTcpServerLogging( registers_context( args.registers ), framer=framer, address=address )
         except KeyboardInterrupt:
             return 1
-        except Exception, e:
+        except Exception as exc:
             log.info( "Couldn't start PLC simulator on %s:%s: %s" % (
                     address[0], address[1], traceback.format_exc()))
 

misc.py

@@ -38,6 +38,7 @@
 import sys
 import time
 import timeit
+import types
 
 try:
     import reprlib
@@ -85,12 +86,66 @@ def isinf( f ):
         return abs( f ) == inf
     math.isinf = isinf
 
+def change_function( function, **kwds ):
+    """Change a function with one or more changed co_... attributes, eg.:
+
+            change_function( func, co_filename="new/file/path.py" )
+
+    will change the func's co_filename to the specified string.
+
+    The types.CodeType constructor differs between Python 2 and 3; see
+    type help(types.CodeType) at the interpreter prompt for information:
+
+    Python2:
+        code(argcount,                nlocals, stacksize, flags, codestring,
+         |        constants, names, varnames, filename, name, firstlineno,
+         |        lnotab[, freevars[, cellvars]])
+
+    Python3:
+        code(argcount, kwonlyargcount, nlocals, stacksize, flags, codestring,
+         |        constants, names, varnames, filename, name, firstlineno,
+         |        lnotab[, freevars[, cellvars]])
+
+
+    """
+    # Enumerate  all the __code__ attributes in the same order; types.CodeTypes
+    # doesn't accept keyword args, only position.
+    attrs			= [ "co_argcount" ]
+    if sys.version_info.major >= 3:
+        attrs		       += [ "co_kwonlyargcount" ]
+    attrs		       += [ "co_nlocals",
+                                    "co_stacksize",
+                                    "co_flags",
+                                    "co_code",
+                                    "co_consts",
+                                    "co_names",
+                                    "co_varnames",
+                                    "co_filename",
+                                    "co_name",
+                                    "co_firstlineno",
+                                    "co_lnotab",
+                                    "co_freevars",
+                                    "co_cellvars" ]
+
+    assert all( k in attrs for k in kwds ), \
+        "Invalid function keyword(s) supplied: %s" % ( ", ".join( kwds.keys() ))
+
+    # Alter the desired function attributes, and update the function's __code__
+    modi_args			= [ kwds.get( a, getattr( function.__code__, a )) for a in attrs ]
+    modi_code			= types.CodeType( *modi_args )
+    modi_func			= types.FunctionType( modi_code, function.__globals__ )
+    function.__code__		= modi_func.__code__
+
 # 
 # logging.normal	-- regular program output 
 # logging.detail	-- detail in addition to normal output
 # 
 #     Augment logging with some new levels, between INFO and WARNING, used for normal/detail output.
 # 
+#     Unfortunationly, logging uses a fragile method to find the logging function's name in the call
+# stack; it looks for the first function whose co_filename is *not* the logger source file.  So, we
+# need to change our functions to appear as if they originated from logging._srcfile.
+# 
 #      .WARNING 	       == 30
 logging.NORMAL			= logging.INFO+5
 logging.DETAIL			= logging.INFO+3
@@ -107,6 +162,9 @@ def __detail( self, msg, *args, **kwargs ):
     if self.isEnabledFor( logging.DETAIL ):
         self._log( logging.DETAIL, msg, args, **kwargs )
 
+change_function( __normal, co_filename=logging._srcfile )
+change_function( __detail, co_filename=logging._srcfile )
+
 logging.Logger.normal		= __normal
 logging.Logger.detail		= __detail
 
@@ -120,6 +178,8 @@ def __detail_root( msg, *args, **kwargs ):
         basicConfig()
     logging.root.detail( msg, *args, **kwargs )
 
+change_function( __normal_root, co_filename=logging._srcfile )
+change_function( __detail_root, co_filename=logging._srcfile )
 logging.normal			= __normal_root
 logging.detail			= __detail_root
 

misc_test.py

@@ -4,6 +4,7 @@
 import logging
 import os
 import sys
+import types
 
 from .misc import *
 
@@ -48,3 +49,17 @@ def test_natural():
     s = sorted( l, key=natural )
     rs = [ repr(i) for i in s ]
     assert rs == ls1 or rs == ls2
+
+def test_function_creation():
+    """Creating functions with code containing a defined co_filename is required in
+    order to extend the logging module.  Unfortunately, this module seeks up the
+    stack frame until it finds a function whose co_filename is not the logging
+    module...  """
+
+    def func( boo ):
+        pass
+
+    assert func.__code__.co_filename == __file__
+    filename			= "something/else.py"
+    change_function( func, co_filename=filename )
+    assert func.__code__.co_filename == filename

remote/plc_modbus.py

@@ -158,9 +158,9 @@ def connect(self):
         try:
             self.socket		= socket.create_connection( (self.host, self.port),
                                     timeout=timeout, source_address=getattr( self, 'source_address', None ))
-        except socket.error, msg:
-            log.debug('Connection to (%s, %s) failed: %s' % \
-                (self.host, self.port, msg))
+        except socket.error as exc:
+            log.debug('Connection to (%s, %s) failed: %s' % (
+                self.host, self.port, exc ))
             self.close()
         finally:
             log.debug( "Connect completed in %.3fs" % ( misc.timer() - begun ))

remote_test.py

@@ -41,8 +41,6 @@
 from   cpppo.remote.plc	import (poller, poller_simulator, PlcOffline)
 from   cpppo.remote.io	import (motor)
 
-#cpppo.log_cfg['level'] = logging.DETAIL
-logging.basicConfig( **cpppo.log_cfg )
 log				= logging.getLogger(__name__)
 
 has_pymodbus			= False
@@ -52,8 +50,8 @@
     from pymodbus.exceptions import ModbusException
     from remote.plc_modbus import (poller_modbus, merge, shatter, ModbusTcpServerActions)
     has_pymodbus		= True
-except Exception as exc:
-    logging.warning( "Failed to import pymodbus module; skipping Modbus/TCP related tests: %s", exc )
+except Exception:
+    logging.warning( "Failed to import pymodbus module; skipping Modbus/TCP related tests; run 'pip install pymodbus'" )
 
 
 @pytest.fixture(scope="module")

requirements-optional.txt

@@ -1 +1,2 @@
+web.py>=0.37
 pymodbus>=1.2.0

requirements.txt

@@ -1,2 +1 @@
 greenery>=1.1,<2.0
-web.py>=0.37

server/echo_test.py

@@ -6,7 +6,6 @@
 import os
 import random
 import socket
-import sys
 import threading
 import time
 import traceback
@@ -16,16 +15,9 @@
 except ImportError:
     import repr as reprlib
 
-if __name__ == "__main__" and __package__ is None:
-    # Allow relative imports when executing within package directory, for
-    # running tests directly
-    sys.path.insert( 0, os.path.dirname(os.path.dirname(os.path.dirname(os.path.abspath(__file__)))))
-
 import cpppo
 from   cpppo.server import *
 
-logging.basicConfig( **cpppo.log_cfg )
-#logging.getLogger().setLevel( logging.DEBUG )
 log				= logging.getLogger( "echo.cli")
 
 

server/enip/__main__.py

@@ -32,4 +32,4 @@
 
 from .main import main
 
-sys.exit( main( argv=sys.argv[1:] ))
+sys.exit( main() )

server/enip/client.py

@@ -252,9 +252,12 @@ def read( self, path, elements=1, offset=0, route_path=None, send_path=None, tim
 
 
 def main( argv=None ):
-    if argv is None:
-        argv			= []
+    """Read the specified tag(s).  Pass the desired argv (excluding the program
+    name in sys.arg[0]; typically pass argv=None, which is equivalent to
+    argv=sys.argv[1:], the default for argparse.  Requires at least one tag to
+    be defined.
 
+    """
     ap				= argparse.ArgumentParser(
         description = "An EtherNet/IP Client",
         epilog = "" )
@@ -266,6 +269,8 @@ def main( argv=None ):
                      default=( "%s:%d" % enip.address ),
                      help="EtherNet/IP interface[:port] to connect to (default: %s:%d)" % (
                          enip.address[0], enip.address[1] ))
+    ap.add_argument( '-l', '--log',
+                     help="Log file, if desired" )
     ap.add_argument( '-t', '--timeout',
                      default=5.0,
                      help="EtherNet/IP timeout (default: 5s)" )
@@ -290,11 +295,13 @@ def main( argv=None ):
         3: logging.INFO,
         4: logging.DEBUG,
         }
-    level			= ( levelmap[args.verbose] 
+    cpppo.log_cfg['level']	= ( levelmap[args.verbose] 
                                     if args.verbose in levelmap
                                     else logging.DEBUG )
-    rootlog			= logging.getLogger("")
-    rootlog.setLevel( level )
+    if args.log:
+        cpppo.log_cfg['filename'] = args.log
+
+    logging.basicConfig( **cpppo.log_cfg )
 
     timeout			= float( args.timeout )
     repeat			= int( args.repeat )
@@ -320,7 +327,7 @@ def main( argv=None ):
         break
     elapsed			= misc.timer() - begun
     log.normal( "Client Register Rcvd %7.3f/%7.3fs: %s" % ( elapsed, timeout, enip.enip_format( data )))
-    assert data is not None or 'CIP.register' not in data, "Failed to receive Register response"
+    assert data is not None and 'enip.CIP.register' in data, "Failed to receive Register response"
     assert data.enip.status == 0, "Register response indicates failure: %s" % data.enip.status
 
     cli.session			= data.enip.session_handle
@@ -381,4 +388,4 @@ def main( argv=None ):
     log.warning( "Client ReadFrg. Average %7.3f TPS (%7.3fs ea)." % ( repeat / duration, duration / repeat ))
 
 if __name__ == "__main__":
-    sys.exit( main( argv=sys.argv[1:] ))
+    sys.exit( main() )