basic logging added

Logging messages from the main process to graylog.
Just the scan time and the timeout are recorded in graylog.
Statistics will be easy to see.
The processes run as part of multiprocessing are not included in the logs
for now.
I didn't find an easy way to do this.

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._ui.resetCountdown()
         self._camera_switch.restart_live_capture_from_side()
@@ -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)