Merge pull request #73 from DiamondLightSource/logs_new

basic logging added

Author: UrszulaNeuman

dls_barcode/camera/camera_scanner.py

@@ -2,6 +2,7 @@
 
 import multiprocessing
 import queue
+import logging
 
 from .capture_worker import CaptureWorker
 from .scanner_worker import ScannerWorker
@@ -49,29 +50,31 @@ def __init__(self, result_queue, view_queue, message_queue, config):
     def start_scan(self, cam_position):
         """ Spawn the processes that will continuously capture and process images from the camera.
         """
-        print("\nMAIN: start triggered")
+        log = logging.getLogger(".".join([__name__, self.__class__.__name__]))
+        log.debug("8) scan start triggered")
         scanner_args = (self._task_q, self._overlay_q, self._result_q, self._message_q, self._scanner_kill_q, self._config, cam_position)
         self._scanner_process = multiprocessing.Process(target=CameraScanner._scanner_worker, args=scanner_args)
 
         self._capture_command_q.put(CaptureCommand(StreamAction.START, cam_position))
         self._scanner_process.start()
 
     def stop_scan(self):
-        print("\nMAIN: Stop triggered")
+        log = logging.getLogger(".".join([__name__, self.__class__.__name__]))
+        log.debug("stop triggered")
         self._terminate_scanner_process()
         self._capture_command_q.put(CaptureCommand(StreamAction.STOP))
-        print("MAIN: Stop completed")
+        log.debug("stop scan completed")
 
     def kill(self):
-        print("\n__________")
-        print("MAIN: Kill")
+        log = logging.getLogger(".".join([__name__, self.__class__.__name__]))
+        log.debug("Kill")
         self.stop_scan()
         self._capture_kill_q.put(None)
-        print("MAIN: forcing capture cleanup")
+        log.debug("KILL forcing capture cleanup")
         self._process_cleanup(self._capture_process, [self._task_q, self._view_q])
         self._capture_process.join()
         self._flush_queue(self._capture_kill_q)
-        print("MAIN: KILL COMPLETED")
+        log.debug("KILL COMPLETED")
 
     def _flush_queue(self, queue):
         while not queue.empty():
@@ -80,12 +83,13 @@ def _flush_queue(self, queue):
     def _terminate_scanner_process(self):
         if self._scanner_process is not None:
             self._scanner_kill_q.put(None)
-            print("MAIN: forcing scanner cleanup")
+            log = logging.getLogger(".".join([__name__, self.__class__.__name__]))
+            log.debug("starting scanner process cleanup")
             self._process_cleanup(self._scanner_process, [self._result_q, self._overlay_q, self._message_q])
             self._scanner_process.join()
             self._flush_queue(self._scanner_kill_q)
             self._scanner_process = None
-            print("MAIN: scanner rejoined")
+            log.debug("scanner process cleared and rejoined - caused by stop scan")
 
     def _process_cleanup(self, process, queues):
         """ A sub-process that writes to a queue can't terminate if the queue is not empty.
@@ -96,11 +100,12 @@ def _process_cleanup(self, process, queues):
             https://stackoverflow.com/questions/31708646/process-join-and-queue-dont-work-with-large-numbers
         """
         # Put the process in a list so we don't need to check is_alive() every time - supposed to perform better
+        log = logging.getLogger(".".join([__name__, self.__class__.__name__]))
         live_processes = [process]
         display = True
         while live_processes:
             if display:
-                print("MAIN: sub-process still alive")
+                log.debug("scanner process still alive")
                 display = False
 
             for q in queues:
@@ -115,7 +120,7 @@ def _process_cleanup(self, process, queues):
 
             live_processes = [p for p in live_processes if p.is_alive()]
 
-        print("MAIN: sub-process terminated!")
+        log.debug("scanner process terminated by process cleanup")
 
     @staticmethod
     def _capture_worker(task_queue, view_queue, overlay_queue, command_queue, kill_queue, camera_configs):

dls_barcode/camera/camera_switch.py

@@ -1,3 +1,4 @@
+import logging
 import time
 from .camera_position import CameraPosition
 
@@ -18,6 +19,8 @@ def _stop_live_capture(self):
     def restart_live_capture_from_side(self):
         self._stop_live_capture()
         self._switch_to_side()
+        log = logging.getLogger(".".join([__name__]))
+        log.debug("6) starting scan from side")
         self._scanner.start_scan(CameraPosition.SIDE)
 
     def restart_live_capture_from_top(self):

dls_barcode/datamatrix/read/interpret.py

@@ -1,3 +1,6 @@
+import logging
+
+
 class DatamatrixByteInterpreter:
     @staticmethod
     def interpret_bytes(data_bytes):
@@ -46,13 +49,20 @@ def interpret_bytes(data_bytes):
                 i += num_bytes
 
             elif byte == 240:
+                #log = log = logging.getLogger(".".join([__name__]))
+                #log.error(NotImplementedError("Datamatrix EDIFACT decoding not implemented"))
                 raise NotImplementedError("Datamatrix EDIFACT decoding not implemented")
 
             elif byte == 241:
+                #log = log = logging.getLogger(".".join([__name__]))
+                #log.error(NotImplementedError("Datamatrix Extended Channel Interpretation code not implemented"))
                 raise NotImplementedError("Datamatrix Extended Channel Interpretation code not implemented")
 
             elif 242 <= byte < 256 or byte == 0:  # Unused parts of message space.
-                raise ValueError("Code {} is not used in Datamatrix specification".format(byte))
+                #log = log = logging.getLogger(".".join([__name__]))
+                error = ValueError("Code {} is not used in Datamatrix specification".format(byte))
+                #.error(error)
+                raise error
 
         return ''.join(m for m in message)
 

dls_barcode/main.py

@@ -1,8 +1,10 @@
+import logging
 import sys
 
 from os.path import dirname
 from sys import path
-
+import pygelf
+import logconfig
 from dls_barcode.config import BarcodeConfig
 from dls_barcode.gui import DiamondBarcodeMainWindow
 from dls_barcode.main_manager import MainManager
@@ -31,12 +33,17 @@ def main(config_file, version):
     ui = DiamondBarcodeMainWindow(config, version, None)
     manager = MainManager(ui, config)
     manager.initialise_timers()
+    log = logging.getLogger(".".join([__name__]))
+    log.debug('2) timers initialised')
     manager.initialise_scanner()
     sys.exit(app.exec_())
 
 
 if __name__ == '__main__':
+    logconfig.setup_logging()
+    #logconfig.set_additional_handler("log.log")
     # Multiprocessing support for PyInstaller bundling in Windows
+    log = logging.getLogger(".".join([__name__]))
     if sys.platform.startswith('win'):
         import multiprocessing
         multiprocessing.freeze_support()
@@ -45,6 +52,7 @@ def main(config_file, version):
     parser.add_argument("-cf", "--config_file", type=str, default=DEFAULT_CONFIG_FILE,
                         help="The path of the configuration file (default=" + DEFAULT_CONFIG_FILE + ")")
     args = parser.parse_args()
-    print("CONFIG: " + args.config_file)
+    log.info("CONFIG: " + args.config_file)
+    #print("CONFIG: " + args.config_file)
 
     main(args.config_file, VERSION)

dls_barcode/main_manager.py

@@ -1,3 +1,4 @@
+import logging
 import multiprocessing
 import queue
 import time
@@ -54,19 +55,27 @@ def _cleanup(self):
         self._ui.resetCountdown()
 
     def initialise_scanner(self):
+        log = logging.getLogger(".".join([__name__]))
+        log.debug("3) camera scanner initialisation")
         self._camera_scanner = CameraScanner(self._result_queue, self._view_queue, self._message_queue, self._config)
+        log.debug("4) camera switch initialisation")
         self._camera_switch = CameraSwitch(self._camera_scanner, self._config.top_camera_timeout)
+
         self._restart_live_capture_from_side()
         self._ui.resetCountdown()
 
     def _camera_capture_alive(self):
         return self._camera_scanner is not None and self._camera_switch is not None
 
     def _restart_live_capture_from_top(self):
+        log = logging.getLogger(".".join([__name__]))
+        log.debug("starting live capture form top")
         self._camera_switch.restart_live_capture_from_top()
         self._ui.startCountdown(self._config.top_camera_timeout.value())
 
     def _restart_live_capture_from_side(self):
+        log = logging.getLogger(".".join([__name__]))
+        log.debug("5) starting live capture form side")
         self._reset_msg_timer()
         self._camera_switch.restart_live_capture_from_side()
         self._ui.resetCountdown()
@@ -138,7 +147,8 @@ def _read_side_scan(self):
 
         # Barcode successfully read
         Beeper.beep()
-        print("MAIN: puck barcode recorded")
+        log = logging.getLogger(".".join([__name__]))
+        log.debug("puck barcode recorded")
         holder_barcode = plate.barcodes()[0]
         if not self._ui.isLatestHolderBarcode(holder_barcode):
             self._latest_holder_barcode = holder_barcode
@@ -149,8 +159,10 @@ def _read_top_scan(self):
         if self._result_queue.empty():
             if self._camera_switch.is_top_scan_timeout():
                 self._ui.displayScanTimeoutMessage()
-
-                print("\n*** Scan timeout ***")
+                log = logging.getLogger(".".join([__name__]))
+                extra = ({"timeout_value": 1})
+                log = logging.LoggerAdapter(log, extra)
+                log.info("scan timeout", extra)
                 self._restart_live_capture_from_side()
             return
 
@@ -165,5 +177,8 @@ def _read_top_scan(self):
 
         # Barcodes successfully read
         Beeper.beep()
-        print("Scan Completed", self._camera_switch.get_scan_time())
+        log = logging.getLogger(".".join([__name__]))
+        extra = ({"scan_time": self._camera_switch.get_scan_time(), "timeout_value": 0})
+        log = logging.LoggerAdapter(log, extra)
+        log.info("Scan Completed", extra)
         self._restart_live_capture_from_side()

dls_barcode/scan/with_geometry/geometry_scanner.py

@@ -60,7 +60,7 @@ def _perform_frame_scan(self):
         self._frame_result.set_barcodes(self._barcodes)
         if self.plate_type == Geometry.UNIPUCK:
             self._geometry = UnipuckLocator(self._frame_img).find_location()
-        if self._geometry == None:
+        if self._geometry is None:
             self._geometry = self._calculate_geometry()
 
         self._frame_result.set_geometry(self._geometry)
@@ -171,8 +171,8 @@ def _make_slotted_barcodes_list(barcodes, geometry):
         slotted_bcs = [None] * geometry.num_slots()
         for bc in barcodes:
             slot_num = geometry.containing_slot(bc.center())
-            if(slot_num != None):
-                slotted_bcs[slot_num -  1] = bc
+            if slot_num is not None:
+                slotted_bcs[slot_num - 1] = bc
 
         return slotted_bcs
 

dls_barcode/version.py

@@ -1 +1 @@
-VERSION = "v1.3.0"
+VERSION = "v1.4.0"

dls_util/cv/camera_stream.py

@@ -1,3 +1,5 @@
+import logging
+
 import cv2 as opencv
 
 _OPENCV_MAJOR = opencv.__version__[0]

logconfig.py

@@ -0,0 +1,130 @@
+""" logconfig
+This is essentially a template which can be copied into a python project and
+used to easily achieve a good practice of logging. Modify the local copy as per
+the project or site requirements.
+"""
+
+import os
+import json
+import logging.config
+import logging.handlers
+import getpass
+import threading
+
+
+from dls_barcode import version
+
+MAXBYTES = 1048576
+BACKUPCOUNT = 20
+ENCODING = "utf8"
+
+
+default_config = {
+    "version": 1.0,
+    "disable_existing_loggers": False,
+    "formatters": {
+        "simple": {
+            "format": "%(message)s"
+        },
+        "extended": {
+            "format": "%(asctime)s - %(name)20s - %(levelname)6s - %(message)s"
+        },
+        "json": {
+            "format": "name: %(name)s, level: %(levelname)s, time: %(asctime)s, message: %(message)s"
+        }
+    },
+
+    "handlers": {
+        "console": {
+            "class": "logging.StreamHandler",
+            "level": "DEBUG",
+            "formatter": "simple",
+            "stream": "ext://sys.stdout"
+        },
+
+        "graylog_gelf": {
+            "class": "pygelf.GelfUdpHandler",
+            "level": "INFO",
+            # Obviously a DLS-specific configuration: the graylog server address and port
+            # Use the input "Load Balanced GELF TCP" on graylog2.
+            "host": "graylog2",# "localhost", - use locaklhost for tests
+            "port": 12201,
+            "debug": True,
+            #  The following custom fields will be disabled if setting this False
+            "include_extra_fields": True,
+            "username": getpass.getuser(),
+            "pid": os.getpid(),
+            "application": "BarcodeScanner",
+            "facility": "XChem",
+            "_version": version.VERSION
+        },
+
+    },
+    "root": {
+        # Set the level here to be the default minimum level of log record to be produced
+        # If you set a handler to level DEBUG you will need to set either this level
+        "level": "DEBUG",
+        "handlers": ["console", "graylog_gelf"]
+    }
+}
+
+
+class ThreadContextFilter(logging.Filter):
+    """A logging context filter to add thread name and ID."""
+
+    def filter(self, record):
+        record.thread_id = str(threading.current_thread().ident)
+        record.thread_name = str(threading.current_thread().name)
+        return True
+
+
+def setup_logging(
+        default_log_config=None,
+        default_level=logging.INFO,
+        env_key='LOG_CFG'
+):
+    """Setup logging configuration
+    Call this only once from the application main() function or __main__ module!
+    This will configure the python logging module based on a logging configuration
+    in the following order of priority:
+       1. Log configuration file found in the environment variable specified in the `env_key` argument.
+       2. Log configuration file found in the `default_log_config` argument.
+       3. Default log configuration found in the `logconfig.default_config` dict.
+       4. If all of the above fails: basicConfig is called with the `default_level` argument.
+    Args:
+        default_log_config (Optional[str]): Path to log configuration file.
+        env_key (Optional[str]): Environment variable that can optionally contain
+            a path to a configuration file.
+        default_level (int): logging level to set as default. Ignored if a log
+            configuration is found elsewhere.
+    Returns: None
+    """
+    dict_config = None
+
+    logconfig_filename = default_log_config
+    env_var_value = os.getenv(env_key, None)
+
+    if env_var_value is not None:
+        logconfig_filename = env_var_value
+
+    if default_config is not None:
+        dict_config = default_config
+
+    if logconfig_filename is not None and os.path.exists(logconfig_filename):
+        with open(logconfig_filename, 'rt') as f:
+            file_config = json.load(f)
+        if file_config is not None:
+            dict_config = file_config
+
+    if dict_config is not None:
+        logging.config.dictConfig(dict_config)
+    else:
+        logging.basicConfig(level=default_level)
+
+
+def set_additional_handler(file_name):
+    logger = logging.getLogger()
+    handler = logging.handlers.RotatingFileHandler(file_name, maxBytes=MAXBYTES, backupCount=BACKUPCOUNT, encoding=ENCODING)
+    #json_format = default_config.get("formatters",{}).get("json",{}).get("format",{})
+    #handler.setFormatter(logging.Formatter(json_format))
+    logger.addHandler(handler)