Device: replace Device._logger with module loggers (issue #110)

Each device instance has its own logger.  This was meant to help in
filter the log records by device.  This was achieved by having
DeviceServer get the logger with that device name and have records
from it written to a properly named file.  However, this meant that
log record from other loggers were discarded and has since been
changed.  This means that there's no longer need for each Device to
have its own instance and can instead used module loggers as is
recommended in the documentation and is standard in other packages.

This commits removes the Device._logger attribute and replaces all its
use with loggers from the individual modules.

Author: carandraug

microscope/cameras/andorsdk3.py

@@ -22,6 +22,7 @@
 a camera and all its settings to be exposed over Pyro.
 """
 
+import logging
 import queue
 import time
 
@@ -34,6 +35,9 @@
 from .SDK3Cam import *
 
 
+_logger = logging.getLogger(__name__)
+
+
 # SDK data pointer type
 DPTR_TYPE = SDK3.POINTER(SDK3.AT_U8)
 
@@ -322,7 +326,7 @@ def set_num_buffers(self, num):
 
     def _purge_buffers(self):
         """Purge buffers on both camera and PC."""
-        self._logger.debug("Purging buffers.")
+        _logger.debug("Purging buffers.")
         self._buffers_valid = False
         if self._acquiring:
             raise Exception ('Can not modify buffers while camera acquiring.')
@@ -340,7 +344,7 @@ def _create_buffers(self, num=None):
         if num is None:
             num = self.num_buffers
         self._purge_buffers()
-        self._logger.debug("Creating %d buffers." % num)
+        _logger.debug("Creating %d buffers." % num)
         self._img_stride = self._aoi_stride.get_value()
         self._img_width = self._aoi_width.get_value()
         self._img_height = self._aoi_height.get_value()
@@ -372,7 +376,7 @@ def _fetch_data(self, timeout=5, debug=False):
             ptr, length = SDK3.WaitBuffer(self.handle, timeout)
         except SDK3.TimeoutError as e:
             if debug:
-                self._logger.debug(e)
+                _logger.debug(e)
             return None
         except Exception:
             raise
@@ -395,7 +399,7 @@ def _fetch_data(self, timeout=5, debug=False):
 
     def abort(self):
         """Abort acquisition."""
-        self._logger.debug('Disabling acquisition.')
+        _logger.debug('Disabling acquisition.')
         if self._acquiring:
             self._acquisition_stop()
 
@@ -447,7 +451,7 @@ def initialize(self):
             self._trigger_mode.set_string('Software')
             self._cycle_mode.set_string('Continuous')
         else:
-            self._logger.warn("No hardware found - using SIMCAM")
+            _logger.warn("No hardware found - using SIMCAM")
 
 
         def callback(*args):
@@ -485,15 +489,15 @@ def _on_disable(self):
         self._buffers_valid = False
 
     def _on_enable(self):
-        self._logger.debug("Preparing for acquisition.")
+        _logger.debug("Preparing for acquisition.")
         if self._acquiring:
             self._acquisition_stop()
         self._create_buffers()
         try:
             self._acquisition_start()
         except Exception as e:
             raise Exception(str(e))
-        self._logger.debug("Acquisition enabled: %s." % self._acquiring)
+        _logger.debug("Acquisition enabled: %s." % self._acquiring)
         return True
 
     @keep_acquiring
@@ -503,7 +507,7 @@ def set_exposure_time(self, value):
                       value))[1]
         self._exposure_time.set_value(bounded_value)
         self._frame_rate.set_value(self._frame_rate.max())
-        self._logger.debug("Set exposure time to %f, resulting framerate %f."
+        _logger.debug("Set exposure time to %f, resulting framerate %f."
                           % (bounded_value, self._frame_rate.get_value()))
 
     def get_exposure_time(self):

microscope/cameras/atmcd.py

@@ -29,6 +29,8 @@
 
    Tested against Ixon Ultra with atmcd64d.dll ver 2.97.30007.0 .
 """
+
+import logging
 import re, sys, functools, os, platform
 import ctypes
 from ctypes import Structure, POINTER
@@ -37,6 +39,10 @@
 from ctypes import c_void_p
 from numpy.ctypeslib import ndpointer
 
+
+_logger = logging.getLogger(__name__)
+
+
 # Andor docs use Windows datatypes in call signatures. These may not be available on
 # other platforms.
 try:
@@ -1191,7 +1197,7 @@ def _acquiring(self, value):
 
     def abort(self):
         """Abort acquisition."""
-        self._logger.debug('Disabling acquisition.')
+        _logger.debug('Disabling acquisition.')
         try:
             with self:
                 AbortAcquisition()
@@ -1209,7 +1215,7 @@ def _set_cooler_state(self, state):
 
     def initialize(self):
         """Initialize the library and hardware and create Setting objects."""
-        self._logger.info('Initializing ...')
+        _logger.info('Initializing ...')
         num_cams = GetAvailableCameras()
         if self._index >= num_cams:
             msg = "Requested camera %d, but only found %d cameras" % (self._index, num_cams)
@@ -1244,7 +1250,7 @@ def initialize(self):
                     for s in range(GetNumberHSSpeeds(ch, amp.value)):
                         speed = GetHSSpeed(ch, amp.value, s)
                         self._readout_modes.append(ReadoutMode(ch, amp, s, speed))
-            self._logger.info("... initilized %s s/n %s" % (model, serial))
+            _logger.info("... initilized %s s/n %s" % (model, serial))
         ## Add settings. Some are write-only, so we set defaults here.
         # Mode
         name = 'readout mode'
@@ -1394,18 +1400,19 @@ def _on_shutdown(self):
         with self:
             CoolerOFF()
 
-        self._logger.info("Waiting for temperature to rise above -20C before shutdown ...")
+        _logger.info('Waiting for temperature to rise above -20C'
+                     ' before shutdown ...')
 
         while True:
             # Check temperature then release lock.
             with self:
                 t = GetTemperature()[1]
-                self._logger.info("... T = %dC" % t)
+                _logger.info("... T = %dC" % t)
             if t > -20:
                 break
             time.sleep(10)
 
-        self._logger.info("Temperature is %dC: shutting down camera." % t)
+        _logger.info("Temperature is %dC: shutting down camera." % t)
 
         with self:
             ShutDown()
@@ -1478,7 +1485,7 @@ def get_cycle_time(self):
     def _set_readout_mode(self, mode_index):
         """Configure channel, amplifier and VS-speed."""
         mode = self._readout_modes[mode_index]
-        self._logger.info("Setting readout mode to %s" % mode)
+        _logger.info("Setting readout mode to %s" % mode)
         with self:
             SetADChannel(mode.channel)
             SetOutputAmplifier(mode.amp)

microscope/cameras/pvcam.py

@@ -128,6 +128,7 @@
 """
 
 import ctypes
+import logging
 import os
 import platform
 import time
@@ -139,6 +140,10 @@
 from microscope.devices import ROI, Binning
 from microscope.devices import keep_acquiring
 
+
+_logger = logging.getLogger(__name__)
+
+
 # Readout transform mapping - {CHIP_NAME: {port: transform}}
 READOUT_TRANSFORMS = {
     'Evolve-5': {0: (0,0,0),
@@ -1081,7 +1086,8 @@ def _query(self, what=ATTR_CURRENT, force_query=False):
                 result = ctypes.POINTER(self._ctype)(result).contents.value
         # Test on err.args prevents indexing into empty tuple.
         if err and err.args and err.args[0].startswith('pvcam error 49'):
-            self.cam._logger.warn("Parameter %s not available due to camera state." % self.name)
+            _logger.warn("Parameter %s not available due to camera state."
+                         % self.name)
             result = None
         elif err:
             raise e
@@ -1259,7 +1265,7 @@ def cb():
                 """Soft trigger mode end-of-frame callback."""
                 timestamp = time.time()
                 frame = self._buffer.copy()
-                self._logger.debug("Fetched single frame.")
+                _logger.debug("Fetched single frame.")
                 _exp_finish_seq(self.handle, CCS_CLEAR)
                 self._put(frame, timestamp)
                 return
@@ -1280,7 +1286,7 @@ def cb():
                 timestamp = time.time()
                 frame_p = ctypes.cast(_exp_get_latest_frame(self.handle), ctypes.POINTER(uns16))
                 frame = np.ctypeslib.as_array(frame_p, (self.roi[2], self.roi[3])).copy()
-                self._logger.debug("Fetched frame from circular buffer.")
+                _logger.debug("Fetched frame from circular buffer.")
                 self._put(frame, timestamp)
                 return
             # Need to keep a reference to the callback.
@@ -1333,7 +1339,7 @@ def _on_shutdown(self):
         _cam_close(self.handle)
         PVCamera.open_cameras.remove(self.handle)
         if not PVCamera.open_cameras:
-            self._logger.info("No more open cameras - calling _pvcam_uninit.")
+            _logger.info("No more open cameras - calling _pvcam_uninit.")
             _pvcam_uninit()
 
 
@@ -1400,18 +1406,18 @@ def initialize(self):
             _pvcam_uninit()
             raise Exception ('No cameras detected.')
         # Connect to the camera.
-        self._logger.info("DLL version: %s" % _pvcam_get_ver().value)
+        _logger.info("DLL version: %s" % _pvcam_get_ver().value)
         self._pv_name = _cam_get_name(self._index).value
-        self._logger.info('Initializing %s' % self._pv_name)
+        _logger.info('Initializing %s' % self._pv_name)
         self.handle = _cam_open(self._pv_name, OPEN_EXCLUSIVE)
         PVCamera.open_cameras.append(self.handle)
         # Set up event callbacks. Tried to use the resume callback to reinit camera
         # after power loss, but any attempt to close/reopen the camera or deinit the
         # DLL throws a Windows Error 0xE06D7363.
         def _cb(event):
-            self._logger.info("Received %s event." % event)
+            _logger.info("Received %s event." % event)
             if event == 'removed':
-                self._logger.critical("Can not re-init hardware. Exiting.")
+                _logger.critical("Can not re-init hardware. Exiting.")
                 exit(-1)
             return
         self._cbs = {'check': CALLBACK(lambda: _cb('check')),
@@ -1426,7 +1432,7 @@ def _cb(event):
             try:
                 p = PVParam.factory(self, param_id)
             except:
-                self._logger.warn("Skipping unsupported parameter %s." % name)
+                _logger.warn("Skipping unsupported parameter %s." % name)
                 continue
             if not p.dtype or not p.available:
                 continue
@@ -1441,7 +1447,8 @@ def _cb(event):
             except Exception as err:
                 # Test on err.args prevents indexing into empty tuple.
                 if err.args and not err.args[0].startswith('pvcam error 49'):
-                    self._logger.warn("Skipping parameter %s: not supported in python." % (p.name))
+                    _logger.warn('Skipping parameter %s: not supported'
+                                 ' in python.' % (p.name))
                     continue
             self.add_setting(p.name,
                              p.dtype,
@@ -1554,14 +1561,16 @@ def soft_trigger(self):
         Trigger an exposure in TRIG_SOFT mode.
         Log some debugging stats in other trigger modes."""
         if self._trigger == TRIG_SOFT:
-            self._logger.debug("Received soft trigger ...")
+            _logger.debug("Received soft trigger ...")
             _exp_start_seq(self.handle, self._buffer.ctypes.data_as(ctypes.c_void_p))
         else:
             cstatus, cbytes, cframes = _exp_check_cont_status(self.handle)
             status, bytes = _exp_check_status(self.handle)
 
-            self._logger.debug("Status checks\ncheck_cont:   %s \t bytes: %d\tframes: %d\n"  \
-                               "check_status: %s \t bytes: %d\t" \
-                               % (STATUS_STRINGS[cstatus.value], cbytes.value, cframes.value,
-                                  STATUS_STRINGS[status.value], bytes.value))
+            _logger.debug('Status checks\n'
+                          'check_cont:   %s \t bytes: %d\tframes: %d\n'
+                          'check_status: %s \t bytes: %d\t'
+                          % (STATUS_STRINGS[cstatus.value], cbytes.value,
+                             cframes.value, STATUS_STRINGS[status.value],
+                             bytes.value))
         return

microscope/cameras/ximea.py

@@ -19,6 +19,8 @@
 ## You should have received a copy of the GNU General Public License
 ## along with Microscope.  If not, see <http://www.gnu.org/licenses/>.
 
+import logging
+
 import numpy as np
 
 from microscope import devices
@@ -28,6 +30,9 @@
 from ximea import xiapi
 
 
+_logger = logging.getLogger(__name__)
+
+
 # Trigger mode to type.
 TRIGGER_MODES = {
     'internal': None,
@@ -59,13 +64,13 @@ def __init__(self, **kwargs):
     def _fetch_data(self):
         if self._acquiring and self._triggered:
             self.handle.get_image(self.img)
-            self._logger.info('Sending image')
+            _logger.info('Sending image')
             self._triggered = False
             data = np.array(list(self.img.get_image_data_raw()),dtype=np.uint16).reshape(self.img.width,self.img.height)
             return data
 
     def abort(self):
-        self._logger.info('Disabling acquisition.')
+        _logger.info('Disabling acquisition.')
         if self._acquiring:
             self._acquiring = False
         self.handle.stop_acquisition()
@@ -82,7 +87,7 @@ def initialize(self):
             raise Exception("Problem opening camera.")
         if self.handle == None:
             raise Exception("No camera opened.")
-        self._logger.info('Initializing.')
+        _logger.info('Initializing.')
         self.img=xiapi.Image()
 
     def make_safe(self):
@@ -93,13 +98,13 @@ def _on_disable(self):
         self.abort()
 
     def _on_enable(self):
-        self._logger.info("Preparing for acquisition.")
+        _logger.info("Preparing for acquisition.")
         if self._acquiring:
             self.abort()
         self._acquiring = True
         #actually start camera
         self.handle.start_acquisition()
-        self._logger.info("Acquisition enabled.")
+        _logger.info("Acquisition enabled.")
         return True
 
     def set_exposure_time(self, value):
@@ -134,8 +139,8 @@ def set_trigger_type(self, trigger):
             self.handle.set_gpi_mode(XI_GPI_TRIGGER)
 
     def soft_trigger(self):
-        self._logger.info('Trigger received; self._acquiring is %s.'
-                          % self._acquiring)
+        _logger.info('Trigger received; self._acquiring is %s.'
+                     % self._acquiring)
         if self._acquiring:
             self._triggered = True