def test_aaa(self):
# root
with self.assertLogs() as log:
get_logger(self).info('Message')
rec: LogRecord = log.records.pop(0)
self.assertEqual(rec.name, 'root')
self.assertEqual(rec.levelno, LogLevel.INFO)
self.assertEqual(rec.args, ())
self.assertEqual(rec.module, 'test_logging')
self.assertEqual(rec.filename, 'test_logging.py')
self.assertEqual(rec.funcName, 'test_aaa')
self.assertEqual(rec.topic, '')
self.assertEqual(rec.agent, 'test_aaa (test_logging.TestLogging)')
self.assertEqual(rec.context, UNDEFINED)
self.assertEqual(rec.message, 'Message')
# trace
with self.assertLogs() as log:
get_logger(self, topic='trace').info('Message')
rec = log.records.pop(0)
self.assertEqual(rec.name, 'trace')
self.assertEqual(rec.levelno, LogLevel.INFO)
self.assertEqual(rec.args, ())
self.assertEqual(rec.module, 'test_logging')
self.assertEqual(rec.filename, 'test_logging.py')
self.assertEqual(rec.funcName, 'test_aaa')
self.assertEqual(rec.topic, 'trace')
self.assertEqual(rec.agent, 'test_aaa (test_logging.TestLogging)')
self.assertEqual(rec.context, UNDEFINED)
self.assertEqual(rec.message, 'Message')
def action(self, delay: int) -> None:
"""Scheduled action.
"""
get_logger(self).info("Scheduled action, {delay=}", delay=delay)
#sleep(1.5)
if not self._heap:
self.stop.set()
def aquire_resources(self) -> None:
"""Aquire resources required by component (open files, connect to other services etc.).
Must raise an exception when resource aquisition fails.
"""
get_logger(self).info("Aquiring resources...")
if self._fail_on is FailOn.RESOURCE_AQUISITION:
raise Error("Service configured to fail")
def test_null_logger(self):
with self.assertLogs() as log:
get_logger(self).info('Message')
rec: LogRecord = log.records.pop(0)
self.assertEqual(rec.message, 'Message')
install_null_logger()
bind_logger(ANY, ANY, 'null')
with self.assertRaises(AssertionError) as cm:
with self.assertLogs() as log:
get_logger(self).info('Message')
self.assertEqual(cm.exception.args, ("no logs of level INFO or higher triggered on root",))
def start_activities(self) -> None:
"""Start normal component activities.
Must raise an exception when start fails.
"""
get_logger(self).info("Starting activities...")
if self._fail_on is FailOn.ACTIVITY_START:
raise Error("Service configured to fail")
if self._schedule:
for delay in self._schedule:
self.schedule(partial(self.action, delay), delay)
def release_resources(self) -> None:
"""Release resources aquired by component (close files, disconnect from other services etc.)
"""
get_logger(self).info("Releasing resources...")
# CLOSE all active data pipe sessions
chn: Channel = self.mngr.channels[PIPE_CHN]
# send_close() will discard session, so we can't iterate over sessions.values() directly
for session in list(chn.sessions.values()):
# We have to report error here, because normal is to close pipes before
# shutdown is commenced. Mind that service shutdown could be also caused by error!
cast(FBDPServer, chn.protocol).send_close(chn, session,
ErrorCode.ERROR)
def aquire_resources(self) -> None:
"""Aquire resources required by component (open files, connect to other services etc.).
Must raise an exception when resource aquisition fails.
"""
get_logger(self).info("Aquiring resources...")
# Connect to the data pipe
if self.pipe_mode == SocketMode.CONNECT:
chn: Channel = self.mngr.channels[PIPE_CHN]
session = chn.connect(self.pipe_address)
# OPEN the data pipe connection, this also fills session attributes
cast(FBDPClient,
chn.protocol).send_open(chn, session, self.data_pipe,
self.pipe_socket, self.file_format)
# We work with MIME formats, so we'll convert the format specification to MIME
session.data_format = MIME(session.data_format)
session.charset = session.data_format.params.get(
'charset', 'ascii')
session.errors = session.data_format.params.get('errors', 'strict')
self._open_file()
def stop(self, *, timeout: int = 10000) -> None:
"""Stop all runing services in bundle. The services are stopped in the reverse
order in which they were started.
Arguments:
timeout: Timeout for stopping each service. None (infinity), or a floating
point number specifying a timeout for the operation in seconds (or
fractions thereof) [Default: 10s].
Raises:
ServiceError: On error in communication with service.
TimeoutError: When service does not stop in time.
"""
for controller in reversed(self.services):
try:
controller.stop(timeout=timeout)
except Exception as exc:
get_logger(self).error(
"Error while stopping the service: {args[0]}", exc)
if controller.is_running():
warnings.warn(
f"Stopping service {controller.name} failed, service thread terminated",
RuntimeWarning)
controller.terminate()
def initialize(self, config: DummyConfig) -> None:
"""Verify configuration and assemble component structural parts.
"""
super().initialize(config)
self.log_context = 'main'
get_logger(self).info("Initialization...")
self._fail_on: FailOn = config.fail_on.value
get_logger(self).info("{fail_on=}", fail_on=self._fail_on)
self._schedule: List[int] = config.schedule.value
get_logger(self).info("{schedule=}", schedule=self._schedule)
if self._fail_on is FailOn.INIT:
raise Error("Service configured to fail")
def test_interpolation(self):
data = ['interpolation', 'breakdown', 'overflow']
# Using keyword arguments
with self.assertLogs() as log:
get_logger(self).info('Information {data}', data=data[0])
rec: LogRecord = log.records.pop(0)
self.assertEqual(rec.message, 'Information interpolation')
# Using positional dictionary
with self.assertLogs() as log:
get_logger(self).info('Information {data}', {'data': data[1]})
rec = log.records.pop(0)
self.assertEqual(rec.message, 'Information breakdown')
# Using positional args
with self.assertLogs() as log:
get_logger(self).info('Information {args[0][2]}', data)
rec = log.records.pop(0)
self.assertEqual(rec.message, 'Information overflow')
def main():
"""Runs bundle of services.
"""
parser: ArgumentParser = ArgumentParser(
PROG_NAME,
description=main.__doc__,
formatter_class=ArgumentDefaultsHelpFormatter)
parser.add_argument('service',
metavar='SERVICE-CONFIG',
help="Path to service configuration file")
parser.add_argument(
'-c',
'--config',
metavar='CONFIG',
action='append',
help=
"Path to additional configuration file. Could be specified multiple times."
)
parser.add_argument('-s',
'--section',
help="Configuration section name",
default='bundle')
parser.add_argument('-o',
'--outcome',
action='store_true',
help="Always print service execution outcome",
default=False)
parser.add_argument('-l',
'--log-level',
action=UpperAction,
choices=[
x.lower() for x in logging._nameToLevel
if isinstance(x, str)
],
help="Logging level")
args = parser.parse_args()
main_config: ConfigParser = ConfigParser(
interpolation=ExtendedInterpolation())
mngr: ChannelManager = None
log: Logger = None
try:
cfg_files = []
cfg_files.append(str(site.scheme.logging_conf))
if args.config:
cfg_files.extend(args.config)
cfg_files.append(args.service)
cfg_files = main_config.read(cfg_files)
# Logging configuration
if main_config.has_section('loggers'):
fileConfig(main_config)
else:
logging.basicConfig(format=LOG_FORMAT)
log = get_logger(PROG_NAME)
if args.log_level is not None:
log.setLevel(args.log_level)
# trace configuration
if main_config.has_section('trace'):
trace_manager.load_config(main_config)
#
mngr: ChannelManager = ChannelManager(zmq.Context.instance())
mngr.log_context = PROG_NAME
executor: BundleThreadController = BundleThreadController(manager=mngr)
executor.log_context = PROG_NAME
executor.config.read(cfg_files)
executor.configure(section=args.section)
# run services
start = datetime.now()
executor.start()
try:
executor.join()
raise KeyboardInterrupt(
) # This, or direct call to executor.stop()
except KeyboardInterrupt: # SIGINT
executor.stop()
finally:
for svc in executor.services:
if svc.outcome is not Outcome.OK or args.outcome:
print(f'{svc.name} outcome:', svc.outcome.value)
if svc.details:
for line in svc.details:
print(' ', line)
print('Execution time:', datetime.now() - start)
except Exception as exc:
if log:
log.exception("Service execution failed")
parser.exit(1, f'{exc!s}\n')
finally:
if mngr is not None:
mngr.shutdown(forced=True)
logging.shutdown()
zmq.Context.instance().term()
def stop_activities(self) -> None:
"""Stop component activities.
"""
get_logger(self).info("Stopping activities...")
def start_activities(self) -> None:
"""Start normal component activities.
Must raise an exception when start fails.
"""
get_logger(self).info("Starting activities...")
def initialize(self, config: TextIOConfig) -> None:
"""Verify configuration and assemble component structural parts.
"""
super().initialize(config)
get_logger(self).info("Initialization...")
self.log_context = 'main'
# Configuration
self.stop_on_close = config.stop_on_close.value
get_logger(self).debug('{stop_on_close=}',
stop_on_close=self.stop_on_close)
self.data_pipe: str = config.data_pipe.value
get_logger(self).debug('{data_pipe=}', data_pipe=self.data_pipe)
self.pipe_mode: SocketMode = config.pipe_mode.value
get_logger(self).debug('{pipe_mode=}', pipe_mode=self.pipe_mode)
self.pipe_address: ZMQAddress = config.pipe_address.value
get_logger(self).debug('{pipe_address=}',
pipe_address=self.pipe_address)
self.pipe_format: MIME = config.pipe_format.value
get_logger(self).debug('{pipe_format=}', pipe_format=self.pipe_format)
self.pipe_batch_size: int = config.pipe_batch_size.value
get_logger(self).debug('{pipe_batch_size=}',
pipe_batch_size=self.pipe_batch_size)
self.filename: str = config.filename.value
get_logger(self).debug('{filename=}', filename=self.filename)
self.file_mode: FileOpenMode = config.file_mode.value
get_logger(self).debug('{file_mode=}', file_mode=self.file_mode)
self.file_format: MIME = config.file_format.value
get_logger(self).debug('{file_format=}', file_format=self.file_format)
if self.file_format.mime_type != 'text/plain':
raise StopError("Only 'text/plain' MIME type supported")
#
self.is_reader: bool = self.file_mode in [
FileOpenMode.READ, FileOpenMode.APPEND
]
get_logger(self).debug('{is_reader=}', is_reader=self.is_reader)
self.pipe_socket: PipeSocket = None
if self.pipe_mode == SocketMode.BIND:
if self.is_reader:
# Readers BIND to OUTPUT
self.pipe_socket = PipeSocket.OUTPUT
else:
# Writers BIND to INPUT
self.pipe_socket = PipeSocket.INPUT
protocol = FBDPServer(session_type=_Session)
protocol.on_exception = self.handle_exception
protocol.on_accept_client = self.handle_accept_client
protocol.on_get_ready = self.handle_get_ready
protocol.on_schedule_ready = self.handle_schedule_ready
# We have an endpoint to bind
self.endpoints[PIPE_CHN] = [self.pipe_address]
else:
if self.is_reader:
# Readers CONNECT to INPUT
self.pipe_socket = PipeSocket.INPUT
else:
# Writers CONNECT to OUTPUT
self.pipe_socket = PipeSocket.OUTPUT
protocol = FBDPClient(session_type=_Session)
protocol.on_server_ready = self.handle_server_ready
protocol.batch_size = self.pipe_batch_size
protocol.on_pipe_closed = self.handle_pipe_closed
# We assign event handlers unconditionally, but it's also possible to assign only
# really used handlers
protocol.on_accept_data = self.handle_accept_data
protocol.on_produce_data = self.handle_produce_data
protocol.on_data_confirmed = self.handle_data_confirmed
get_logger(self).debug('{pipe_socket=}', pipe_socket=self.pipe_socket)
# Example high water mark optimization
if self.pipe_socket is PipeSocket.OUTPUT:
rcvhwm = 5
sndhwm = self.pipe_batch_size + 5
else:
rcvhwm = self.pipe_batch_size + 5
sndhwm = 5
self.file: IO = None
# Create pipe channel
chn: Channel = self.mngr.create_channel(DealerChannel,
PIPE_CHN,
protocol,
wait_for=Direction.IN,
sock_opts={
'rcvhwm': rcvhwm,
'sndhwm': sndhwm,
})
chn.protocol.log_context = self.logging_id
def main():
"""Runs one service, either unmanaged in main thread, or managed in separate thread.
"""
parser: ArgumentParser = ArgumentParser(
PROG_NAME,
description=main.__doc__,
formatter_class=ArgumentDefaultsHelpFormatter)
parser.add_argument('service',
metavar='SERVICE-CONFIG',
help="Path to service configuration file")
parser.add_argument(
'-c',
'--config',
metavar='CONFIG',
action='append',
help=
"Path to additional configuration file. Could be specified multiple times."
)
parser.add_argument('-s',
'--section',
help="Configuration section name",
default='service')
parser.add_argument('-o',
'--outcome',
action='store_true',
help="Always print service execution outcome",
default=False)
parser.add_argument('--main-thread',
action='store_true',
help="Start the service in main thread",
default=False)
parser.add_argument('-l',
'--log-level',
action=UpperAction,
choices=[
x.lower() for x in logging._nameToLevel
if isinstance(x, str)
],
help="Logging level")
args = parser.parse_args()
main_config: ConfigParser = ConfigParser(
interpolation=ExtendedInterpolation())
# Defaults
main_config[DEFAULTSECT]['here'] = getcwd()
#: Could be used to stop the service in debugger session
debug_stop: bool = False
log: Logger = None
try:
# Read config
cfg_files = []
cfg_files.append(str(site.scheme.logging_conf))
if args.config:
cfg_files.extend(args.config)
cfg_files.append(args.service)
cfg_files = main_config.read(cfg_files)
# Logging configuration
if main_config.has_section('loggers'):
fileConfig(main_config)
else:
logging.basicConfig(format=LOG_FORMAT)
log = get_logger(PROG_NAME)
if args.log_level is not None:
log.setLevel(args.log_level.upper())
# trace configuration
if main_config.has_section('trace'):
trace_manager.load_config(main_config)
#
if not main_config.has_section(args.section):
raise StopError(f"Missing configuration section '{args.section}'")
svc_executor_config: ServiceExecConfig = ServiceExecConfig(
args.section)
svc_executor_config.load_config(main_config)
entries = get_service_desciptors(str(svc_executor_config.agent.value))
if not entries:
raise StopError(
f"Unregistered agent '{svc_executor_config.agent.value}'")
service_desc: ServiceDescriptor = entries[0]
#
if args.main_thread:
executor: DirectController = DirectController(service_desc)
else:
executor: ThreadController = ThreadController(service_desc)
executor.log_context = PROG_NAME
executor.configure(main_config, args.section)
# run the service
executor.start(timeout=10000 if sys.gettrace() is None else None)
if not args.main_thread:
try:
while True:
executor.join(1)
# This, or direct call to executor.stop()
if debug_stop or not executor.is_running():
raise KeyboardInterrupt()
except KeyboardInterrupt: # SIGINT
print()
try:
executor.stop()
except TimeoutError:
executor.terminate()
except Exception as exc:
if log:
log.error("Error while stopping the service")
finally:
if executor.outcome is not Outcome.OK or args.outcome:
print('Outcome:', executor.outcome.value)
if executor.details:
print('Details:')
for line in executor.details:
print(line)
except Exception as exc:
if log:
log.error("Service execution failed")
parser.exit(1, f'{exc!s}\n')
finally:
logging.shutdown()
zmq.Context.instance().term()
def test_bind(self):
LOG_AC = 'test.agent.ctx'
LOG_AX = 'test.agent.ANY'
LOG_XC = 'test.ANY.ctx'
LOG_XX = 'test.ANY.ANY'
ctx = Namespace()
ctx.logging_id = 'CONTEXT'
ctx_B = Namespace()
ctx_B.logging_id = 'B-CONTEXT'
agent = Namespace()
agent.logging_id = 'AGENT'
agent_B = Namespace()
agent_B.logging_id = 'B-AGENT'
#
logging_manager.bind_logger(agent, ctx, LOG_AC)
logging_manager.bind_logger(agent, ANY, LOG_AX)
logging_manager.bind_logger(ANY, ctx, LOG_XC)
# root logger unmasked
with self.assertLogs(level='DEBUG') as log:
get_logger(agent_B, ctx_B).debug('General:B-Agent:B-context')
rec: LogRecord = log.records.pop(0)
self.assertEqual(rec.name, 'root')
# this will mask the root logger, we also test the `bind_logger()`
bind_logger(ANY, ANY, LOG_XX)
#
self.assertTrue(BindFlag.ANY_AGENT in logging_manager.bindings)
self.assertTrue(BindFlag.ANY_CTX in logging_manager.bindings)
self.assertTrue(BindFlag.ANY_ANY in logging_manager.bindings)
self.assertTrue(BindFlag.DIRECT in logging_manager.bindings)
self.assertEqual(len(logging_manager.loggers), 4)
self.assertEqual(len(logging_manager.topics), 1)
self.assertEqual(logging_manager.topics[''], 4)
#
with self.assertLogs(level='DEBUG') as log:
get_logger(agent, ctx).debug('General:Agent:Context')
rec = log.records.pop(0)
self.assertEqual(rec.name, LOG_AC)
#
with self.assertLogs(level='DEBUG') as log:
get_logger(agent, ctx_B).debug('General:Agent:B-context')
rec = log.records.pop(0)
self.assertEqual(rec.name, LOG_AX)
#
with self.assertLogs(level='DEBUG') as log:
get_logger(agent, ANY).debug('General:Agent:ANY')
rec = log.records.pop(0)
self.assertEqual(rec.name, LOG_AX)
#
with self.assertLogs(level='DEBUG') as log:
get_logger(agent).debug('General:Agent:UNDEFINED')
rec = log.records.pop(0)
self.assertEqual(rec.name, LOG_AX)
#
with self.assertLogs(level='DEBUG') as log:
get_logger(agent_B, ctx).debug('General:B-Agent:Context')
rec = log.records.pop(0)
self.assertEqual(rec.name, LOG_XC)
#
with self.assertLogs(level='DEBUG') as log:
get_logger(context=ctx).debug('General:UNDEFINED:Context')
rec = log.records.pop(0)
self.assertEqual(rec.name, LOG_XC)
#
with self.assertLogs(level='DEBUG') as log:
get_logger(agent_B, ctx_B).debug('General:B-Agent:B-context')
rec = log.records.pop(0)
self.assertEqual(rec.name, LOG_XX)
#
with self.assertLogs(level='DEBUG') as log:
get_logger().debug('General:UNDEFINED:UNDEFINED')
rec = log.records.pop(0)
self.assertEqual(rec.name, LOG_XX)
def stop_activities(self) -> None:
"""Stop component activities.
"""
get_logger(self).info("Stopping activities...")
if self._fail_on is FailOn.ACTIVITY_STOP:
raise Error("Service configured to fail")
def release_resources(self) -> None:
"""Release resources aquired by component (close files, disconnect from other services etc.)
"""
get_logger(self).info("Releasing resources...")
if self._fail_on is FailOn.RESOURCE_RELEASE:
raise Error("Service configured to fail")
