Pass the % format args to loggers instead of doing formatting ourselves.

We call Logger.debug (or any other logging level) with a message but
we don't know if that message will be emitted.  If it never gets
emitted, it's a waste to format the message.

So instead of doing the % formatting format ourselves with %, this
commit passes the unformatted message and the % args to the Logger
which delays the formatting until it knows the message will actually
be emitted.

Author: carandraug

microscope/cameras/andorsdk3.py

@@ -344,7 +344,7 @@ def _create_buffers(self, num=None):
         if num is None:
             num = self.num_buffers
         self._purge_buffers()
-        _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()
@@ -497,7 +497,7 @@ def _on_enable(self):
             self._acquisition_start()
         except Exception as e:
             raise Exception(str(e))
-        _logger.debug("Acquisition enabled: %s." % self._acquiring)
+        _logger.debug("Acquisition enabled: %s.", self._acquiring)
         return True
 
     @keep_acquiring
@@ -507,8 +507,8 @@ def set_exposure_time(self, value):
                       value))[1]
         self._exposure_time.set_value(bounded_value)
         self._frame_rate.set_value(self._frame_rate.max())
-        _logger.debug("Set exposure time to %f, resulting framerate %f."
-                          % (bounded_value, self._frame_rate.get_value()))
+        _logger.debug("Set exposure time to %f, resulting framerate %f.",
+                      bounded_value, self._frame_rate.get_value())
 
     def get_exposure_time(self):
         return self._exposure_time.get_value()

microscope/cameras/atmcd.py

@@ -1248,7 +1248,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))
-            _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'
@@ -1399,12 +1399,12 @@ def _on_shutdown(self):
             # Check temperature then release lock.
             with self:
                 t = GetTemperature()[1]
-                _logger.info("... T = %dC" % t)
+                _logger.info("... T = %dC", t)
             if t > -20:
                 break
             time.sleep(10)
 
-        _logger.info("Temperature is %dC: shutting down camera." % t)
+        _logger.info("Temperature is %dC: shutting down camera.", t)
 
         with self:
             ShutDown()
@@ -1477,7 +1477,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]
-        _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

@@ -1086,8 +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'):
-            _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
@@ -1406,16 +1406,16 @@ def initialize(self):
             _pvcam_uninit()
             raise Exception ('No cameras detected.')
         # Connect to the camera.
-        _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
-        _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):
-            _logger.info("Received %s event." % event)
+            _logger.info("Received %s event.", event)
             if event == 'removed':
                 _logger.critical("Can not re-init hardware. Exiting.")
                 exit(-1)
@@ -1432,7 +1432,7 @@ def _cb(event):
             try:
                 p = PVParam.factory(self, param_id)
             except:
-                _logger.warn("Skipping unsupported parameter %s." % name)
+                _logger.warn("Skipping unsupported parameter %s.", name)
                 continue
             if not p.dtype or not p.available:
                 continue
@@ -1448,7 +1448,7 @@ def _cb(event):
                 # Test on err.args prevents indexing into empty tuple.
                 if err.args and not err.args[0].startswith('pvcam error 49'):
                     _logger.warn('Skipping parameter %s: not supported'
-                                 ' in python.' % (p.name))
+                                 ' in python.', p.name)
                     continue
             self.add_setting(p.name,
                              p.dtype,
@@ -1569,8 +1569,8 @@ def soft_trigger(self):
 
             _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))
+                          'check_status: %s \t bytes: %d\t',
+                          STATUS_STRINGS[cstatus.value], cbytes.value,
+                          cframes.value, STATUS_STRINGS[status.value],
+                          bytes.value)
         return

microscope/devices.py

@@ -299,7 +299,7 @@ def get_setting(self, name):
         try:
             return self._settings[name].get()
         except Exception as err:
-            _logger.error("in get_setting(%s):" % (name), exc_info=err)
+            _logger.error("in get_setting(%s):", name, exc_info=err)
             raise
 
     def get_all_settings(self):
@@ -315,7 +315,7 @@ def set_setting(self, name, value):
         try:
             self._settings[name].set(value)
         except Exception as err:
-            _logger.error("in set_setting(%s):" % (name), exc_info=err)
+            _logger.error("in set_setting(%s):", name, exc_info=err)
             raise
 
     def describe_setting(self, name):
@@ -495,8 +495,8 @@ def _send_data(self, client, data, timestamp):
             client.receiveData(data, timestamp)
         except (Pyro4.errors.ConnectionClosedError, Pyro4.errors.CommunicationError):
             # Client not listening
-            _logger.info("Removing %s from client stack: disconnected."
-                         % client._pyroUri)
+            _logger.info("Removing %s from client stack: disconnected.",
+                         client._pyroUri)
             self._clientStack = list(filter(client.__ne__, self._clientStack))
             self._liveClients = self._liveClients.difference([client])
         except:
@@ -592,7 +592,7 @@ def set_client(self, new_client):
         if self._client is None:
             _logger.info("Current client is None.")
         else:
-            _logger.info("Current client is %s." % str(self._client))
+            _logger.info("Current client is %s.", str(self._client))
 
 
     @keep_acquiring

microscope/deviceserver.py

@@ -225,10 +225,10 @@ def run(self):
         pyro_thread = Thread(target = pyro_daemon.requestLoop)
         pyro_thread.daemon = True
         pyro_thread.start()
-        _logger.info('Serving %s' % pyro_daemon.uriFor(self._device))
+        _logger.info('Serving %s', pyro_daemon.uriFor(self._device))
         if isinstance(self._device, microscope.devices.FloatingDeviceMixin):
-            _logger.info('Device UID on port %s is %s'
-                         % (port, self._device.get_id()))
+            _logger.info('Device UID on port %s is %s',
+                         port, self._device.get_id())
 
         # Wait for termination event. We should just be able to call
         # wait() on the exit_event, but this causes issues with locks
@@ -327,21 +327,21 @@ def keep_alive():
                     continue
                 else:
                     _logger.info("DeviceServer Failure. Process %s is dead with"
-                                 " exitcode %s. Restarting..."
-                                 % (s.pid, s.exitcode))
+                                 " exitcode %s. Restarting...",
+                                 s.pid, s.exitcode)
                     servers.remove(s)
                     servers.append(s.clone())
 
                     try:
                         s.join(30)
                     except:
-                        _logger.error("... could not join PID %s." % (s.pid))
+                        _logger.error("... could not join PID %s.", s.pid)
                     else:
                         old_pid = s.pid
                         del (s)
                         servers[-1].start()
                         _logger.info("... DeviceServer with PID %s restarted"
-                                     " as PID %s." % (old_pid, servers[-1].pid))
+                                     " as PID %s.", old_pid, servers[-1].pid)
             if len(servers) == 0:
                 # Log and exit if no servers running. May want to change this
                 # if we add some interface to interactively restart servers.

microscope/lasers/cobolt.py

@@ -134,7 +134,7 @@ def get_max_power_mw(self):
         try:
             return float(response)
         except:
-            _logger.info("Bad response to gmlp?\n    %s" % response.decode())
+            _logger.info("Bad response to gmlp?\n    %s", response.decode())
 
 
     @devices.SerialDeviceMixIn.lock_comms

microscope/lasers/obis.py

@@ -39,25 +39,25 @@ def __init__(self, com, baud=115200, timeout=0.5, **kwargs) -> None:
         # Start a logger.
         self._write(b'SYSTem:INFormation:MODel?')
         response = self._readline()
-        _logger.info('OBIS laser model: [%s]' % response.decode())
+        _logger.info('OBIS laser model: [%s]', response.decode())
         self._write(b'SYSTem:INFormation:SNUMber?')
         response = self._readline()
-        _logger.info('OBIS laser serial number: [%s]' % response.decode())
+        _logger.info('OBIS laser serial number: [%s]', response.decode())
         self._write(b'SYSTem:CDRH?')
         response = self._readline()
-        _logger.info('CDRH safety: [%s]' % response.decode())
+        _logger.info('CDRH safety: [%s]', response.decode())
         self._write(b'SOURce:TEMPerature:APRobe?')
         response = self._readline()
-        _logger.info('TEC temperature control: [%s]' % response.decode())
+        _logger.info('TEC temperature control: [%s]', response.decode())
         self._write(b'*TST?')
         response = self._readline()
-        _logger.info('Self test procedure: [%s]' % response.decode())
+        _logger.info('Self test procedure: [%s]', response.decode())
 
         # We need to ensure that autostart is disabled so that we can
         # switch emission on/off remotely.
         self._write(b'SYSTem:AUTostart?')
         response = self._readline()
-        _logger.info('Response to Autostart: [%s]' % response.decode())
+        _logger.info('Response to Autostart: [%s]', response.decode())
 
     def _write(self, command):
         """Send a command."""
@@ -101,7 +101,7 @@ def enable(self):
         self._flush_handshake()
         self._write(b'SOURce:AM:STATe?')
         response = self._readline()
-        _logger.info("SOURce:AM:STATe? [%s]" % response.decode())
+        _logger.info("SOURce:AM:STATe? [%s]", response.decode())
 
         if not self.get_is_on():
             # Something went wrong.

microscope/lasers/sapphire.py

@@ -58,7 +58,7 @@ def __init__(self, com=None, baud=19200, timeout=0.5, **kwargs):
         # Head ID value is a float point value,
         # but only the integer part is significant
         headID = int(float(self.send(b'?hid')))
-        _logger.info("Sapphire laser serial number: [%s]" % headID)
+        _logger.info("Sapphire laser serial number: [%s]", headID)
 
     def _write(self, command):
         count = super()._write(command)
@@ -132,7 +132,7 @@ def _on_enable(self):
         _logger.info("Turning laser ON.")
         # Turn on emission.
         response = self.send(b'l=1')
-        _logger.info("l=1: [%s]" % response.decode())
+        _logger.info("l=1: [%s]", response.decode())
 
         # Enabling laser might take more than 500ms (default timeout)
         prevTimeout = self.connection.timeout
@@ -177,7 +177,7 @@ def get_power_mw(self):
     @devices.SerialDeviceMixIn.lock_comms
     def _set_power_mw(self, mW):
         mW_str = '%.3f' % mW
-        _logger.info("Setting laser power to %s mW." % mW_str)
+        _logger.info("Setting laser power to %s mW.", mW_str)
         # using send instead of _write, because
         # if laser is not on, warning is returned
         return self.send(b'p=%s' % mW_str.encode())

microscope/testsuite/devices.py

@@ -238,7 +238,7 @@ def _fetch_data(self):
             return image
 
     def abort(self):
-        _logger.info("Disabling acquisition; %d images sent." % self._sent)
+        _logger.info("Disabling acquisition; %d images sent.", self._sent)
         if self._acquiring:
             self._acquiring = False
 
@@ -283,8 +283,8 @@ def get_trigger_type(self):
         return devices.TRIGGER_SOFT
 
     def soft_trigger(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 += 1
 
@@ -316,7 +316,7 @@ def get_position(self):
 
     def set_position(self, position):
         time.sleep(1)
-        _logger.info("Setting position to %s" % position)
+        _logger.info("Setting position to %s", position)
         self._position = position
 
     def initialize(self):
@@ -354,7 +354,7 @@ def get_is_on(self):
         return self._emission
 
     def _set_power_mw(self, level):
-        _logger.info("Power set to %s." % level)
+        _logger.info("Power set to %s.", level)
         self._power = level
 
     def get_max_power_mw(self):
@@ -401,7 +401,7 @@ def _on_shutdown(self):
         pass
 
     def set_sim_diffraction_angle(self, theta):
-        _logger.info('set_sim_diffraction_angle %f' % theta)
+        _logger.info('set_sim_diffraction_angle %f', theta)
         self.sim_diffraction_angle = theta
 
     def get_sim_diffraction_angle(self):
@@ -447,15 +447,15 @@ def Abort(self):
         _logger.info('Abort')
 
     def WriteDigital(self, value):
-        _logger.info('WriteDigital: %s' % "{0:b}".format(value))
+        _logger.info('WriteDigital: %s', bin(value))
         self._digi = value
 
     def MoveAbsolute(self, aline, pos):
-        _logger.info('MoveAbsoluteADU: line %d, value %d' % (aline, pos))
+        _logger.info('MoveAbsoluteADU: line %d, value %d', aline, pos)
         self._ana[aline] = pos
 
     def arcl(self, mask, pairs):
-        _logger.info('arcl: %s, %s' % (mask, pairs))
+        _logger.info('arcl: %s, %s', mask, pairs)
 
     def profileSet(self, pstr, digitals, *analogs):
         _logger.info('profileSet ...')
@@ -475,12 +475,12 @@ def trigCollect(self, *args, **kwargs):
         _logger.info(kwargs)
 
     def ReadPosition(self, aline):
-        _logger.info('ReadPosition   : line %d, value %d'
-                     % (aline, self._ana[aline]))
+        _logger.info('ReadPosition   : line %d, value %d',
+                     aline, self._ana[aline])
         return self._ana[aline]
 
     def ReadDigital(self):
-        _logger.info('ReadDigital: %s' % "{0:b}".format(self._digi))
+        _logger.info('ReadDigital: %s', bin(self._digi))
         return self._digi
 
     def PrepareActions(self, actions, numReps=1):