1414import subprocess
1515import sys
1616import time
17+ import traceback
18+
19+ log = logging .getLogger ( 'mbs_test' )
1720
1821has_o_nonblock = False
1922try :
2023 import fcntl
2124 has_o_nonblock = True
2225except Exception :
23- logging .warning ( "Failed to import fcntl; skipping simulated Modbus/TCP PLC tests" )
26+ log .warning ( "Failed to import fcntl; skipping simulated Modbus/TCP PLC tests" )
2427
2528from . import misc
2629from .tools .waits import waitfor
@@ -39,15 +42,15 @@ class nonblocking_command( object ):
3942
4043 try:
4144 data = command.stdout.read()
42- logging .debug( "Received %d bytes from command, len( data ))
45+ log .debug( "Received %d bytes from command, len( data ))
4346 collect += data
4447 except IOError as exc:
4548 if exc.errno != errno.EAGAIN:
46- logging .warning( "I/O Error reading data: %s" % traceback.format_exc() )
49+ log .warning( "I/O Error reading data: %s" % traceback.format_exc() )
4750 command = None
4851 # Data not presently available; ignore
4952 except:
50- logging .warning( "Exception reading data: %s", traceback.format_exc() )
53+ log .warning( "Exception reading data: %s", traceback.format_exc() )
5154 command = None
5255
5356 # do other stuff in loop...
@@ -62,32 +65,34 @@ class nonblocking_command( object ):
6265 def __init__ ( self , command , stderr = subprocess .STDOUT , stdin = None , bufsize = 0 , blocking = None ):
6366 shell = type ( command ) is not list
6467 self .command = ' ' .join ( command ) if not shell else command
65- logging .info ( "Starting command: %s" , self .command )
68+ log .info ( "Starting command: %s" , self .command )
6669 self .process = subprocess .Popen (
6770 command , stdout = subprocess .PIPE , stderr = stderr , stdin = stdin ,
6871 bufsize = bufsize , preexec_fn = os .setsid , shell = shell )
72+ log .normal ( 'Started Server PID [%d]: %s' , self .process .pid , self .command )
6973 if not blocking :
7074 fd = self .process .stdout .fileno ()
7175 fl = fcntl .fcntl ( fd , fcntl .F_GETFL )
7276 fcntl .fcntl ( fd , fcntl .F_SETFL , fl | os .O_NONBLOCK )
73-
74- atexit .register ( lambda : self .kill () )
77+ # Really, really ensure we get terminated
78+ atexit .register ( self .kill )
7579
7680 @property
7781 def stdout ( self ):
7882 return self .process .stdout
7983
8084 def kill ( self ):
81- logging .info ( 'Sending SIGTERM to PID [%d]: %s' , self .process .pid , self .command )
85+ log .normal ( 'Sending SIGTERM to PID [%d]: %s, via: %s' , self .process .pid , self .command ,
86+ '' .join ( traceback .format_stack () ) if log .isEnabledFor ( logging .INFO ) else '' )
8287 try :
8388 os .killpg ( self .process .pid , signal .SIGTERM )
8489 except OSError as exc :
85- logging .info ( 'Failed to send SIGTERM to PID [%d]: %s' , self .process .pid , exc )
90+ log .info ( 'Failed to send SIGTERM to PID [%d]: %s' , self .process .pid , exc )
8691 else :
87- logging .info ( "Waiting for command (PID [%d]) to terminate" , self .process .pid )
92+ log .info ( "Waiting for command (PID [%d]) to terminate" , self .process .pid )
8893 self .process .wait ()
8994 # Process may exit with a non-numeric returncode (eg. None)
90- logging .info ( "Command (PID [%d]) finished with status %r: %s" ,
95+ log .info ( "Command (PID [%d]) finished with status %r: %s" ,
9196 self .process .pid , self .process .returncode , self .command )
9297
9398 __del__ = kill
@@ -111,30 +116,30 @@ def start_modbus_simulator( options ):
111116 raw = None
112117 try :
113118 raw = command .stdout .read ()
114- logging .debug ( "Socket received: %r" , raw )
119+ log .debug ( "Socket received: %r" , raw )
115120 if raw :
116121 data += raw .decode ( 'utf-8' , 'backslashreplace' )
117122 except IOError as exc :
118- logging .debug ( "Socket blocking..." )
123+ log .debug ( "Socket blocking..." )
119124 assert exc .errno == errno .EAGAIN , "Expected only Non-blocking IOError"
120125 except Exception as exc :
121- logging .warning ("Socket read return Exception: %s" , exc )
126+ log .warning ("Socket read return Exception: %s" , exc )
122127 if not raw :
123128 time .sleep ( RTU_LATENCY )
124129 while data .find ( '\n ' ) >= 0 :
125130 line ,data = data .split ( '\n ' , 1 )
126- logging .info ( "%s" , line )
131+ log .info ( "%s" , line )
127132 m = re .search ( "address = (.*)" , line )
128133 if m :
129134 try :
130135 host ,port = m .group (1 ).split ( ':' )
131136 address = host ,int (port )
132- logging .normal ( "Modbus/TCP Simulator started after %7.3fs on %s:%d" ,
137+ log .normal ( "Modbus/TCP Simulator started after %7.3fs on %s:%d" ,
133138 misc .timer () - begun , address [0 ], address [1 ] )
134139 except :
135140 assert m .group (1 ).startswith ( '/' )
136141 address = m .group (1 )
137- logging .normal ( "Modbus/RTU Simulator started after %7.3fs on %s" ,
142+ log .normal ( "Modbus/RTU Simulator started after %7.3fs on %s" ,
138143 misc .timer () - begun , address )
139144 break
140145 return command ,address
@@ -209,7 +214,7 @@ def run_plc_modbus_polls( plc ):
209214 r = random .randint ( base , base + extent )
210215 v = plc .read ( r )
211216 if v is not None :
212- logging .detail ( "New reg %5d was already polled due to reach=%d" , r , plc .reach )
217+ log .detail ( "New reg %5d was already polled due to reach=%d" , r , plc .reach )
213218 regs [r ] = v
214219 regs [r ] = ( regs [r ] ^ 1 if r in regs
215220 else random .randint ( 0 , 65535 ) if base > 40000
@@ -225,7 +230,7 @@ def run_plc_modbus_polls( plc ):
225230 assert success
226231 rolling = misc .exponential_moving_average ( rolling , elapsed , rolling_factor )
227232
228- logging .normal ( "%3d/%3d regs: polled %3d ranges w/in %7.3fs. Polled %5d == %5d w/in %7.3fs: avg. %7.3fs (load %3.2f, %3.2f, %3.2f)" ,
233+ log .normal ( "%3d/%3d regs: polled %3d ranges w/in %7.3fs. Polled %5d == %5d w/in %7.3fs: avg. %7.3fs (load %3.2f, %3.2f, %3.2f)" ,
229234 len ( regs ), total , len ( plc .polling ), plc .duration ,
230235 r , regs [r ], elapsed or 0.0 , rolling or 0.0 , * [misc .nan if load is None else load for load in plc .load ] )
231236
0 commit comments