Add logging

sandbox/engulf/behaviour.py

@@ -11,6 +11,13 @@ class GrassGrownUp(Event):
         self.subject_id = subject_id
         self.density = density
 
+    def repr_debug(self) -> str:
+        return '{}: subject_id:{}, density:{}'.format(
+            self.__class__.__name__,
+            self.subject_id,
+            self.density,
+        )
+
 
 class GrassSpawn(Event):
     def __init__(self, subject_id, position, density, *args, **kwargs):
@@ -19,6 +26,14 @@ class GrassSpawn(Event):
         self.position = position
         self.density = density
 
+    def repr_debug(self) -> str:
+        return '{}: subject_id:{}, position:{}, density:{}'.format(
+            self.__class__.__name__,
+            self.subject_id,
+            self.position,
+            self.density,
+        )
+
 
 class GrassSpotablePositionsMechanism(SimulationMechanism):
     parallelizable = True

sandbox/engulf/run.py

@@ -21,12 +21,16 @@ Engulf is simulation containing:
 import os
 import sys
 
+import logging
+
 synergine2_ath = os.path.abspath(os.path.join(os.path.dirname(os.path.abspath(__file__)), '../../'))
 sys.path.append(synergine2_ath)
 
 from random import randint, seed
 from sandbox.engulf.behaviour import GrassGrownUp, GrassSpawn, GrassSpawnBehaviour
 
+from synergine2.config import Config
+from synergine2.log import get_default_logger
 from sandbox.engulf.subject import Cell, Grass, COLLECTION_GRASS
 from synergine2.core import Core
 from synergine2.cycle import CycleManager
@@ -140,12 +144,25 @@ def main():
     )
     simulation.subjects = subjects
 
+    config = Config()
+    logger = get_default_logger(level=logging.DEBUG)
+    logger.debug('HELLO')
     core = Core(
+        config=config,
+        logger=logger,
         simulation=simulation,
-        cycle_manager=CycleManager(simulation=simulation),
-        terminal_manager=TerminalManager([GameTerminal(
-            asynchronous=False,
-        )]),
+        cycle_manager=CycleManager(
+            config=config,
+            logger=logger,
+            simulation=simulation,
+        ),
+        terminal_manager=TerminalManager(
+            config=config,
+            logger=logger,
+            terminals=[GameTerminal(
+                asynchronous=False,
+            )]
+        ),
         cycles_per_seconds=1,
     )
     core.run()

synergine2/base.py

@@ -0,0 +1,6 @@
+# coding: utf-8
+
+
+class BaseObject(object):
+    def repr_debug(self) -> str:
+        return type(self).__name__

synergine2/config.py

@@ -0,0 +1,5 @@
+# coding: utf-8
+
+
+class Config(dict):
+    pass

synergine2/core.py

@@ -1,6 +1,9 @@
 # coding: utf-8
 import time
+
+from synergine2.config import Config
 from synergine2.cycle import CycleManager
+from synergine2.log import SynergineLogger
 from synergine2.simulation import Simulation
 from synergine2.terminals import TerminalManager
 from synergine2.terminals import TerminalPackage
@@ -9,11 +12,15 @@ from synergine2.terminals import TerminalPackage
 class Core(object):
     def __init__(
         self,
+        config: Config,
+        logger: SynergineLogger,
         simulation: Simulation,
         cycle_manager: CycleManager,
         terminal_manager: TerminalManager=None,
         cycles_per_seconds: int=1,
     ):
+        self.config = config
+        self.logger = logger
         self.simulation = simulation
         self.cycle_manager = cycle_manager
         self.terminal_manager = terminal_manager or TerminalManager([])
@@ -21,12 +28,14 @@ class Core(object):
         self._current_cycle_start_time = None
 
     def run(self):
+        self.logger.info('Run core')
         try:
             self.terminal_manager.start()
 
             start_package = TerminalPackage(
                 subjects=self.simulation.subjects,
             )
+            self.logger.info('Send start package to terminals')
             self.terminal_manager.send(start_package)
 
             while True:
@@ -59,14 +68,19 @@ class Core(object):
         self.terminal_manager.stop()
 
     def _start_cycle(self):
-        self._current_cycle_start_time = time.time()
+        time_ = time.time()
+        self.logger.info('Start cycle at time {}'.format(time_))
+        self._current_cycle_start_time = time_
 
     def _end_cycle(self) -> None:
         """
         Make a sleep if cycle duration take less time of wanted (see
         cycles_per_seconds constructor parameter)
         """
-        cycle_duration = time.time() - self._current_cycle_start_time
+        time_ = time.time()
+        self.logger.info('End of cycle at time {}'.format(time_))
+        cycle_duration = time_ - self._current_cycle_start_time
         sleep_time = self._loop_delta - cycle_duration
+        self.logger.info('Sleep time is {}'.format(sleep_time))
         if sleep_time > 0:
             time.sleep(sleep_time)

synergine2/cycle.py

@@ -1,8 +1,11 @@
 # coding: utf-8
 import multiprocessing
 
+from synergine2.config import Config
+from synergine2.log import SynergineLogger
 from synergine2.processing import ProcessManager
-from synergine2.simulation import Subject, SimulationMechanism, SimulationBehaviour
+from synergine2.simulation import SimulationMechanism
+from synergine2.simulation import SimulationBehaviour
 from synergine2.simulation import Simulation
 from synergine2.simulation import SubjectBehaviour
 from synergine2.simulation import SubjectMechanism
@@ -13,6 +16,8 @@ from synergine2.utils import ChunkManager
 class CycleManager(object):
     def __init__(
             self,
+            config: Config,
+            logger: SynergineLogger,
             simulation: Simulation,
             process_manager: ProcessManager=None,
     ):
@@ -22,6 +27,8 @@ class CycleManager(object):
                 chunk_manager=ChunkManager(multiprocessing.cpu_count()),
             )
 
+        self.config = config
+        self.logger = logger
         self.simulation = simulation
         self.process_manager = process_manager
         self.current_cycle = -1
@@ -34,17 +41,26 @@ class CycleManager(object):
             self.first_cycle = False
         self.current_cycle += 1
 
+        self.logger.info('Process cycle {}'.format(self.current_cycle))
+
         events = []
         # TODO: gestion des behaviours non parallelisables
         # TODO: Proposer des ordres d'execution
         events.extend(self._get_subjects_events())
         events.extend(self._get_simulation_events())
 
+        self.logger.info('Cycle {} generate {} events'.format(
+            str(self.current_cycle),
+            str(len(events)),
+        ))
         return events
 
     def _get_simulation_events(self) -> [Event]:
         events = []
         results = {}
+
+        self.logger.info('Process simulation events')
+
         results_by_processes = self.process_manager.execute_jobs(
             data=self.simulation,
             job_maker=self.simulation_computing,
@@ -57,28 +73,64 @@ class CycleManager(object):
                     results.get(behaviour_class),
                 )
 
+        self.logger.info('Simulation generate {} behaviours'.format(len(results)))
+
         # Make events
         for behaviour_class, behaviour_data in results.items():
-            events.extend(self.simulation.behaviours[behaviour_class].action(behaviour_data))
+            behaviour_events = self.simulation.behaviours[behaviour_class].action(behaviour_data)
+            self.logger.info('{} behaviour generate {} events'.format(
+                str(behaviour_class),
+                str(len(behaviour_events)),
+            ))
+
+            if self.logger.is_debug:
+                self.logger.debug('{} behaviour generated events: {}'.format(
+                    str(behaviour_class),
+                    str([e.repr_debug() for e in behaviour_events]),
+                ))
 
+            events.extend(behaviour_events)
+
+        self.logger.info('Simulation behaviours generate {} events'.format(len(events)))
         return events
 
     def _get_subjects_events(self) -> [Event]:
         events = []
+        results = {}
+
+        self.logger.info('Process subjects events')
+
         results_by_processes = self.process_manager.chunk_and_execute_jobs(
             data=self.simulation.subjects,
             job_maker=self.subjects_computing,
         )
-        results = {}
+
         for process_results in results_by_processes:
             results.update(process_results)
-        for subject in self.simulation.subjects[:]:  # Duplicate list to prevent conflicts with behaviours subjects manipulations
+
+        # Duplicate list to prevent conflicts with behaviours subjects manipulations
+        for subject in self.simulation.subjects[:]:
             for behaviour_class, behaviour_data in results.get(subject.id, {}).items():
                 # TODO: Ajouter une etape de selection des actions a faire (genre neuronnal)
                 # (genre se cacher et fuir son pas compatibles)
-                actions_events = subject.behaviours[behaviour_class].action(behaviour_data)
-                events.extend(actions_events)
+                behaviour_events = subject.behaviours[behaviour_class].action(behaviour_data)
+
+                self.logger.info('{} behaviour for subject {} generate {} events'.format(
+                    str(behaviour_class),
+                    str(subject.id),
+                    str(len(behaviour_events)),
+                ))
+
+                if self.logger.is_debug:
+                    self.logger.debug('{} behaviour for subject {} generated events: {}'.format(
+                        str(behaviour_class),
+                        str(subject.id),
+                        str([e.repr_debug() for e in behaviour_events]),
+                    ))
 
+                events.extend(behaviour_events)
+
+        self.logger.info('Subjects behaviours generate {} events'.format(len(events)))
         return events
 
     def simulation_computing(
@@ -87,19 +139,49 @@ class CycleManager(object):
             process_number,
             process_count,
     ):
+        self.logger.info('Simulation computing')
+
         # TODO: necessaire de passer simulation ?
         mechanisms = self.get_mechanisms_to_compute(simulation)
         mechanisms_data = {}
         behaviours_data = {}
 
+        self.logger.info('{} mechanisms to compute'.format(str(len(mechanisms))))
+        if self.logger.is_debug:
+            self.logger.debug('Mechanisms are: {}'.format(
+                str([m.repr_debug() for m in mechanisms])
+            ))
+
         for mechanism in mechanisms:
-            mechanisms_data[type(mechanism)] = mechanism.run(
+            mechanism_data = mechanism.run(
                 process_number=process_number,
                 process_count=process_count,
             )
 
-        for behaviour in self.get_behaviours_to_compute(simulation):
+            if self.logger.is_debug:
+                self.logger.debug('{} mechanism product data: {}'.format(
+                    type(mechanism).__name__,
+                    str(mechanism_data),
+                ))
+
+            mechanisms_data[type(mechanism)] = mechanism_data
+
+        behaviours = self.get_behaviours_to_compute(simulation)
+        self.logger.info('{} behaviours to compute'.format(str(len(behaviours))))
+
+        if self.logger.is_debug:
+            self.logger.debug('Behaviours are: {}'.format(
+                str([b.repr_debug() for b in behaviours])
+            ))
+
+        for behaviour in behaviours:
             behaviour_data = behaviour.run(mechanisms_data)  # TODO: Behaviours dependencies
+            if self.logger.is_debug:
+                self.logger.debug('{} behaviour produce data: {}'.format(
+                    type(behaviour).__name__,
+                    behaviour_data,
+                ))
+
             if behaviour_data:
                 behaviours_data[type(behaviour)] = behaviour_data
 
@@ -112,17 +194,67 @@ class CycleManager(object):
             process_count=None,
     ):
         results = {}
+        self.logger.info('Subjects computing: {} subjects to compute'.format(str(len(subjects))))
+
         for subject in subjects:
             mechanisms = self.get_mechanisms_to_compute(subject)
+            if not mechanisms:
+                break
+
+            self.logger.info('Subject {}: {} mechanisms'.format(
+                str(subject.id),
+                str(len(mechanisms)),
+            ))
+
+            if self.logger.is_debug:
+                self.logger.info('Subject {}: mechanisms are: {}'.format(
+                    str(subject.id),
+                    str([m.repr_debug for m in mechanisms])
+                ))
+
             mechanisms_data = {}
             behaviours_data = {}
 
             for mechanism in mechanisms:
-                mechanisms_data[type(mechanism)] = mechanism.run()
+                mechanism_data = mechanism.run()
+                if self.logger.is_debug:
+                    self.logger.info('Subject {}: {} mechanisms produce data: {}'.format(
+                        str(subject.id),
+                        type(mechanism).__name__,
+                        str(mechanism_data),
+                    ))
+
+                mechanisms_data[type(mechanism)] = mechanism_data
+
+            if self.logger.is_debug:
+                self.logger.info('Subject {}: mechanisms data are: {}'.format(
+                    str(subject.id),
+                    str(mechanisms_data),
+                ))
+
+            subject_behaviours = self.get_behaviours_to_compute(subject)
+
+            self.logger.info('Subject {}: have {} behaviours'.format(
+                str(subject.id),
+                str(len(subject_behaviours)),
+            ))
+
+            for behaviour in subject_behaviours:
+                self.logger.info('Subject {}: run {} behaviour'.format(
+                    str(subject.id),
+                    str(type(behaviour)),
+                ))
 
-            for behaviour in self.get_behaviours_to_compute(subject):
                 # We identify behaviour data with it's class to be able to intersect it after subprocess data collect
                 behaviour_data = behaviour.run(mechanisms_data)  # TODO: Behaviours dependencies
+
+                if self.logger.is_debug:
+                    self.logger.debug('Subject {}: behaviour {} produce data: {}'.format(
+                        str(type(behaviour)),
+                        str(subject.id),
+                        str(behaviour_data),
+                    ))
+
                 if behaviour_data:
                     behaviours_data[type(behaviour)] = behaviour_data
 
@@ -157,6 +289,10 @@ class CycleManager(object):
         simulation_actions = simulation_actions or []
         subject_actions = subject_actions or []
         events = []
+        self.logger.info('Apply {} simulation_actions and {} subject_actions'.format(
+            len(simulation_actions),
+            len(subject_actions),
+        ))
 
         for subject_id, behaviours_and_data in subject_actions:
             subject = self.simulation.subjects.index.get(subject_id)
@@ -165,12 +301,46 @@ class CycleManager(object):
                     simulation=self.simulation,
                     subject=subject,
                 )
-                events.extend(behaviour.action(behaviour_data))
+                self.logger.info('Apply {} behaviour on subject {}'.format(
+                    str(behaviour_class),
+                    str(subject_id),
+                ))
+                if self.logger.is_debug:
+                    self.logger.debug('{} behaviour data is {}'.format(
+                        str(behaviour_class),
+                        str(behaviour_data),
+                    ))
+                behaviour_events = behaviour.action(behaviour_data)
+                self.logger.info('{} events from behaviour {} from subject {}'.format(
+                    len(behaviour_events),
+                    str(behaviour_class),
+                    str(subject_id),
+                ))
+                if self.logger.is_debug:
+                    self.logger.debug('Events from behaviour {} from subject {} are: {}'.format(
+                        str(behaviour_class),
+                        str(subject_id),
+                        str([e.repr_debug() for e in behaviour_events])
+                    ))
+                events.extend(behaviour_events)
 
         for behaviour_class, behaviour_data in simulation_actions:
             behaviour = behaviour_class(
                 simulation=self.simulation,
             )
-            events.extend(behaviour.action(behaviour_data))
 
+            self.logger.info('Apply {} simulation behaviour'.format(
+                str(behaviour_class),
+            ))
+
+            behaviour_events = behaviour.action(behaviour_data)
+            if self.logger.is_debug:
+                self.logger.debug('Events from behaviour {} are: {}'.format(
+                    str(behaviour_class),
+                    str([e.repr_debug() for e in behaviour_events])
+                ))
+
+            events.extend(behaviour_events)
+
+        self.logger.info('{} events generated'.format(len(events)))
         return events

synergine2/exceptions.py

@@ -0,0 +1,11 @@
+# coding: utf-8
+
+
+class SynergineException(Exception):
+    pass
+
+
+class NotYetImplemented(SynergineException):
+    """
+    Like of NotImplementError. Use it to declare method to implement but only if wanted.
+    """

synergine2/log.py

@@ -0,0 +1,27 @@
+# coding: utf-8
+import logging
+
+import sys
+import typing
+
+
+class SynergineLogger(logging.getLoggerClass()):
+    @property
+    def is_debug(self) -> bool:
+        return self.isEnabledFor(logging.DEBUG)
+
+
+def get_default_logger(name: str='synergine', level: int=logging.ERROR) -> SynergineLogger:
+    """
+    WARNING: Set global logging Logger class to SynergineLogger
+    """
+    logging.setLoggerClass(SynergineLogger)
+    logger = logging.getLogger(name)
+    logger = typing.cast(SynergineLogger, logger)
+    handler = logging.StreamHandler(sys.stdout)
+    formatter = logging.Formatter('%(asctime)s|%(name)s|%(process)d|%(levelname)s: %(message)s')
+    handler.setFormatter(formatter)
+    logger.addHandler(handler)
+    logger.setLevel(level)
+
+    return logger

synergine2/simulation.py

@@ -1,6 +1,7 @@
 # coding: utf-8
 import collections
 
+from synergine2.base import BaseObject
 from synergine2.utils import get_mechanisms_classes
 
 
@@ -19,6 +20,15 @@ class Subject(object):
 
         self.initialize()
 
+    def __str__(self):
+        return self.id
+
+    def __repr__(self):
+        return '{}({})'.format(
+            type(self).__name__,
+            self.id,
+        )
+
     def initialize(self):
         for mechanism_class in get_mechanisms_classes(self):
             self.mechanisms[mechanism_class] = mechanism_class(
@@ -103,7 +113,7 @@ class Simulation(object):
             )
 
 
-class SubjectMechanism(object):
+class SubjectMechanism(BaseObject):
     def __init__(
             self,
             simulation: Simulation,
@@ -116,7 +126,7 @@ class SubjectMechanism(object):
         raise NotImplementedError()
 
 
-class SimulationMechanism(object):
+class SimulationMechanism(BaseObject):
     """If parallelizable behaviour, call """
     parallelizable = False
 
@@ -126,16 +136,22 @@ class SimulationMechanism(object):
     ):
         self.simulation = simulation
 
+    def repr_debug(self) -> str:
+        return self.__class__.__name__
+
     def run(self, process_id: int=None, process_count: int=None):
         raise NotImplementedError()
 
 
-class Event(object):
+class Event(BaseObject):
     def __init__(self, *args, **kwargs):
         pass
 
+    def repr_debug(self) -> str:
+        return self.__class__.__name__
+
 
-class SubjectBehaviour(object):
+class SubjectBehaviour(BaseObject):
     frequency = 1
     use = []
 
@@ -166,7 +182,7 @@ class SubjectBehaviour(object):
         raise NotImplementedError()
 
 
-class SimulationBehaviour(object):
+class SimulationBehaviour(BaseObject):
     frequency = 1
     use = []
 

synergine2/terminals.py

@@ -7,13 +7,17 @@ from multiprocessing import Process
 from queue import Empty
 
 import time
+
+from synergine2.base import BaseObject
+from synergine2.config import Config
+from synergine2.log import SynergineLogger
 from synergine2.simulation import Subject
 from synergine2.simulation import Event
 
 STOP_SIGNAL = '__STOP_SIGNAL__'
 
 
-class TerminalPackage(object):
+class TerminalPackage(BaseObject):
     def __init__(
             self,
             subjects: [Subject]=None,
@@ -34,6 +38,18 @@ class TerminalPackage(object):
         self.subject_actions = subject_actions or []
         self.is_cycle = is_cycle
 
+    def repr_debug(self) -> str:
+        subjects = self.subjects or []
+        return str(dict(
+            subjects=subjects,
+            add_subjects=[s.id for s in self.add_subjects],
+            remove_subjects=[s.id for s in self.remove_subjects],
+            events=[e.repr_debug() for e in self.events],
+            simulation_actions=['{}: {}'.format(a.__class__.__name__, p) for a, p in self.simulation_actions],
+            subject_actions=['{}: {}'.format(a.__class__.__name__, p) for a, p in self.subject_actions],
+            is_cycle=self.is_cycle,
+        ))
+
 
 class Terminal(object):
     # Default behaviour is to do nothing.
@@ -118,13 +134,22 @@ class Terminal(object):
 
 
 class TerminalManager(object):
-    def __init__(self, terminals: [Terminal]):
+    def __init__(
+        self,
+        config: Config,
+        logger: SynergineLogger,
+        terminals: [Terminal]
+    ):
+        self.config = config
+        self.logger = logger
         self.terminals = terminals
         self.outputs_queues = {}
         self.inputs_queues = {}
 
     def start(self) -> None:
+        self.logger.info('Start terminals')
         for terminal in self.terminals:
+            # TODO: logs
             output_queue = Queue()
             self.outputs_queues[terminal] = output_queue
 
@@ -142,7 +167,13 @@ class TerminalManager(object):
             output_queue.put(STOP_SIGNAL)
 
     def send(self, package: TerminalPackage):
+        self.logger.info('Send package to terminals')
+        if self.logger.is_debug:
+            self.logger.debug('Send package to terminals: {}'.format(
+                str(package.repr_debug()),
+            ))
         for terminal, output_queue in self.outputs_queues.items():
+            self.logger.info('Send package to terminal {}'.format(terminal.__class__.__name__))
             # Terminal maybe don't want all events, so reduce list of event
             # Thirst make a copy to personalize this package
             terminal_adapted_package = copy(package)
@@ -153,11 +184,22 @@ class TerminalManager(object):
                 if not terminal.accept_event(package_event):
                     terminal_adapted_package.events.remove(package_event)
 
+            if self.logger.is_debug:
+                self.logger.debug('Send package to terminal {}: {}'.format(
+                    terminal.__class__.__name__,
+                    terminal_adapted_package.repr_debug(),
+                ))
+
             output_queue.put(terminal_adapted_package)
 
     def receive(self) -> [TerminalPackage]:
+        self.logger.info('Receive terminals packages')
         packages = []
         for terminal, input_queue in self.inputs_queues.items():
+            self.logger.info('Receive terminal {} packages ({})'.format(
+                terminal.__class__.__name__,
+                'sync' if not terminal.asynchronous else 'async'
+            ))
             # When terminal is synchronous, wait it's cycle package
             if not terminal.asynchronous:
                 continue_ = True
@@ -166,14 +208,28 @@ class TerminalManager(object):
                     # In case where terminal send package before end of cycle
                     # management
                     continue_ = not package.is_cycle
+
+                    if self.logger.is_debug:
+                        self.logger.debug('Receive package from {}: {}'.format(
+                            terminal.__class__.__name__,
+                            str(package.repr_debug()),
+                        ))
+
                     packages.append(package)
             else:
                 try:
                     while True:
-                        packages.append(
-                            input_queue.get(block=False, timeout=None),
-                        )
+                        package = input_queue.get(block=False, timeout=None)
+
+                        if self.logger.is_debug:
+                            self.logger.debug('Receive package from {}: {}'.format(
+                                str(terminal),
+                                str(package.repr_debug()),
+                            ))
+
+                        packages.append(package)
                 except Empty:
                     pass  # Queue is empty
 
+        self.logger.info('{} package(s) received'.format(len(packages)))
         return packages