Log file updates against develop

CONTRIBUTING.md

@@ -33,11 +33,58 @@ playground rules and follow them during all your contributions.
 # Code Formatting
 
 - All Python should use [PEP 8 Standards](https://www.python.org/dev/peps/pep-0008/)
-   - Use a tool such as [yapf](https://github.com/google/yapf) to format your
-     files; we'd rather spend time developing PANOPTES and not arguing about
-     style.
+   - Line length is set at 100 characters instead of 80
+   - It is recommended to have your editor auto-format code whenever you save a file rather than attempt to go back and change an entire file all at once. 
 - Do not leave in commented-out code or unnecessary whitespace.
-- Variable/function/class and file names should be meaningful and descriptive
-- File names should be lower case and underscored, not contain spaces. For
-  example, `my_file.py` instead of `My File.py`
-- Define any project specific terminology or abbreviations you use in the file you use them
+- Variable/function/class and file names should be meaningful and descriptive.
+- File names should be underscored, not contain spaces ex. my_file.py.
+- Define any project specific terminology or abbreviations you use in the file where you use them.
+
+# Log Messages
+
+Use appropriate logging:
+- Log level:
+   - DEBUG (i.e. `self.logger.debug()`) should attempt to capture all run-time information.
+   - INFO (i.e. `self.logger.info()`) should be used sparingly and meant to convey information to a person actively watching a running unit.
+   - WARNING (i.e. `self.logger.warning()`) should alert when something does not go as expected but operation of unit can continue.
+   - ERROR (i.e. `self.logger.error()`) should be used at critical levels when operation cannot continue.
+- The logger supports variable information without the use of the `format` method.
+- There is a `say` method that is meant to be used in friendly manner to convey information to a user. This should be used only for personable output and is typically displayed in the "chat box" of the PAWS website. These messages are also sent to the INFO level logger
+
+#### Logging examples:
+
+_Note: These are meant to illustrate the logging calls and are not necessarily indicative of real operation_
+
+```
+self.logger.info("PANOPTES unit initialized: {}", self.config['name'])
+
+self.say("I'm all ready to go, first checking the weather")
+
+self.logger.debug("Setting up weather station")
+
+self.logger.warning('Problem getting wind safety: {}'.format(e))
+
+self.logger.debug("Rain: {} Clouds: {} Dark: {} Temp: {:.02f}",
+   is_raining,
+   is_cloudy,
+   is_dark,
+   temp_celsius
+)
+
+self.logger.error('Unable to connect to AAG Cloud Sensor, cannot continue')
+```
+
+#### Viewing log files
+
+- You typically want to follow an active log file by using `tail -f` on the command line.
+- The [`grc`](https://github.com/garabik/grc) (generic colouriser) can be used with `tail` to get pretty log files. 
+
+```
+(panoptes-env) $ grc tail -f $PANDIR/logs/pocs_shell.log
+```
+
+The following screenshot shows commands entered into a `jupyter-console` in the top panel and the log file in the bottom panel.
+
+<p align="center">
+   <img src="http://www.projectpanoptes.org/images/log-example.png" width="600">
+</p>

conf_files/log.yaml

@@ -13,9 +13,15 @@ logger:
       all:
         handlers: [all]
         propagate: true
+      info:
+        handlers: [info]
+        propagate: true
       warn:
         handlers: [warn]
         propagate: true
+      error:
+        handlers: [error]
+        propagate: true        
 
     handlers:
       all:
@@ -24,12 +30,24 @@ logger:
         formatter: detail
         when: W6
         backupCount: 4
+      info:
+        class: logging.handlers.TimedRotatingFileHandler
+        level: INFO
+        formatter: detail
+        when: W6
+        backupCount: 4
       warn:
         class: logging.handlers.TimedRotatingFileHandler
         level: WARNING
         formatter: detail
         when: W6
         backupCount: 4
+      error:
+        class: logging.handlers.TimedRotatingFileHandler
+        level: ERROR
+        formatter: detail
+        when: W6
+        backupCount: 4        
 
     root:
       level: DEBUG

pocs/camera/camera.py

@@ -66,7 +66,8 @@ def __init__(self,
             else:
                 # Should have been passed either a Focuser instance or a dict with Focuser
                 # configuration. Got something else...
-                self.logger.error("Expected either a Focuser instance or dict, got {}".format(focuser))
+                self.logger.error(
+                    "Expected either a Focuser instance or dict, got {}".format(focuser))
                 self.focuser = None
         else:
             self.focuser = None
@@ -265,7 +266,9 @@ def command(self, cmd):
                 self._proc = subprocess.Popen(
                     run_cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, universal_newlines=True, shell=False)
             except OSError as e:
-                raise error.InvalidCommand("Can't send command to gphoto2. {} \t {}".format(e, run_cmd))
+                raise error.InvalidCommand(
+                    "Can't send command to gphoto2. {} \t {}".format(
+                        e, run_cmd))
             except ValueError as e:
                 raise error.InvalidCommand("Bad parameters to gphoto2. {} \t {}".format(e, run_cmd))
             except Exception as e:
@@ -379,7 +382,8 @@ def parse_config(self, lines):
                 line = '  {}'.format(line)
             elif IsChoice:
                 if int(IsChoice.group(1)) == 0:
-                    line = '  Choices:\n    {}: {:d}'.format(IsChoice.group(2), int(IsChoice.group(1)))
+                    line = '  Choices:\n    {}: {:d}'.format(
+                        IsChoice.group(2), int(IsChoice.group(1)))
                 else:
                     line = '    {}: {:d}'.format(IsChoice.group(2), int(IsChoice.group(1)))
             elif IsPrintable:

pocs/camera/canon_gphoto2.py

@@ -164,7 +164,9 @@ def take_exposure(self, seconds=1.0 * u.second, filename=None):
         """
         assert filename is not None, self.logger.warning("Must pass filename for take_exposure")
 
-        self.logger.debug('Taking {} second exposure on {}: {}'.format(seconds, self.name, filename))
+        self.logger.debug(
+            'Taking {} second exposure on {}: {}'.format(
+                seconds, self.name, filename))
 
         if isinstance(seconds, u.Quantity):
             seconds = seconds.value

pocs/camera/sbig.py

@@ -190,7 +190,9 @@ def take_exposure(self, seconds=1.0 * u.second, filename=None, dark=False, block
 
         assert filename is not None, self.logger.warning("Must pass filename for take_exposure")
 
-        self.logger.debug('Taking {} second exposure on {}: {}'.format(seconds, self.name, filename))
+        self.logger.debug(
+            'Taking {} second exposure on {}: {}'.format(
+                seconds, self.name, filename))
         exposure_event = Event()
         self._SBIGDriver.take_exposure(self._handle, seconds, filename, exposure_event, dark)
 

pocs/camera/sbigudrv.py

@@ -103,7 +103,9 @@ def __init__(self, library_path=False, *args, **kwargs):
         # Reopen driver ready for next command
         self._send_command('CC_OPEN_DRIVER')
 
-        self.logger.info('\t\t\t SBIGDriver initialised: found {} cameras'.format(self._camera_info.camerasFound))
+        self.logger.info(
+            '\t\t\t SBIGDriver initialised: found {} cameras'.format(
+                self._camera_info.camerasFound))
 
     def __del__(self):
         self.logger.debug('Closing SBIGUDrv driver')
@@ -147,7 +149,8 @@ def assign_handle(self, serial=None):
             try:
                 index = self._handle_assigned.index(False)
             except ValueError:
-                # All handles already assigned, must be trying to intialising more cameras than are connected.
+                # All handles already assigned, must be trying to intialising more cameras
+                # than are connected.
                 self.logger.error('No connected SBIG cameras available!')
                 return (INVALID_HANDLE_VALUE, None)
 
@@ -162,7 +165,8 @@ def assign_handle(self, serial=None):
 
         # Serial number, name and type should match with those from Query USB Info obtained earlier
         camera_serial = str(self._camera_info.usbInfo[index].serialNumber, encoding='ascii')
-        assert camera_serial == ccd_info['serial_number'], self.logger.error('Serial number mismatch!')
+        assert camera_serial == ccd_info['serial_number'], self.logger.error(
+            'Serial number mismatch!')
 
         # Keep camera info.
         self._ccd_info[handle] = ccd_info
@@ -174,7 +178,8 @@ def assign_handle(self, serial=None):
         return (handle, ccd_info)
 
     def query_temp_status(self, handle):
-        query_temp_params = QueryTemperatureStatusParams(temp_status_request_codes['TEMP_STATUS_ADVANCED2'])
+        query_temp_params = QueryTemperatureStatusParams(
+            temp_status_request_codes['TEMP_STATUS_ADVANCED2'])
         query_temp_results = QueryTemperatureStatusResults2()
 
         with self._command_lock:
@@ -262,7 +267,10 @@ def take_exposure(self, handle, seconds, filename, exposure_event=None, dark=Fal
 
         with self._command_lock:
             self._set_handle(handle)
-            self._send_command('CC_QUERY_COMMAND_STATUS', params=query_status_params, results=query_status_results)
+            self._send_command(
+                'CC_QUERY_COMMAND_STATUS',
+                params=query_status_params,
+                results=query_status_results)
 
         if query_status_results.status != status_codes['CS_IDLE']:
             self.logger.warning('Attempt to start exposure on {} while camera busy!'.format(handle))
@@ -290,8 +298,10 @@ def take_exposure(self, handle, seconds, filename, exposure_event=None, dark=Fal
         header.set('CCD-TEMP', temp_status.imagingCCDTemperature)
         header.set('SET-TEMP', temp_status.ccdSetpoint)
         header.set('EGAIN', self._ccd_info[handle]['readout_modes'][readout_mode]['gain'].value)
-        header.set('XPIXSZ', self._ccd_info[handle]['readout_modes'][readout_mode]['pixel_width'].value)
-        header.set('YPIXSZ', self._ccd_info[handle]['readout_modes'][readout_mode]['pixel_height'].value)
+        header.set('XPIXSZ', self._ccd_info[handle]
+                   ['readout_modes'][readout_mode]['pixel_width'].value)
+        header.set('YPIXSZ', self._ccd_info[handle]
+                   ['readout_modes'][readout_mode]['pixel_height'].value)
         if dark:
             header.set('IMAGETYP', 'Dark Frame')
         else:
@@ -347,15 +357,21 @@ def _readout(self, handle, centiseconds, filename, readout_mode_code,
         # Check for the end of the exposure.
         with self._command_lock:
             self._set_handle(handle)
-            self._send_command('CC_QUERY_COMMAND_STATUS', params=query_status_params, results=query_status_results)
+            self._send_command(
+                'CC_QUERY_COMMAND_STATUS',
+                params=query_status_params,
+                results=query_status_results)
 
         # Poll if needed.
         while query_status_results.status != status_codes['CS_INTEGRATION_COMPLETE']:
             self.logger.debug('Waiting for exposure on {} to complete'.format(handle))
             time.sleep(0.1)
             with self._command_lock:
                 self._set_handle(handle)
-                self._send_command('CC_QUERY_COMMAND_STATUS', params=query_status_params, results=query_status_results)
+                self._send_command(
+                    'CC_QUERY_COMMAND_STATUS',
+                    params=query_status_params,
+                    results=query_status_results)
 
         self.logger.debug('Exposure on {} complete'.format(handle))
 
@@ -365,7 +381,11 @@ def _readout(self, handle, centiseconds, filename, readout_mode_code,
             self._send_command('CC_END_EXPOSURE', params=end_exposure_params)
             self._send_command('CC_START_READOUT', params=start_readout_params)
             for i in range(height):
-                self._send_command('CC_READOUT_LINE', params=readout_line_params, results=as_ctypes(image_data[i]))
+                self._send_command(
+                    'CC_READOUT_LINE',
+                    params=readout_line_params,
+                    results=as_ctypes(
+                        image_data[i]))
             self._send_command('CC_END_READOUT', params=end_readout_params)
 
         self.logger.debug('Readout on {} complete'.format(handle))
@@ -407,10 +427,22 @@ def _get_ccd_info(self, handle):
 
         with self._command_lock:
             self._set_handle(handle)
-            self._send_command('CC_GET_CCD_INFO', params=ccd_info_params0, results=ccd_info_results0)
-            self._send_command('CC_GET_CCD_INFO', params=ccd_info_params2, results=ccd_info_results2)
-            self._send_command('CC_GET_CCD_INFO', params=ccd_info_params4, results=ccd_info_results4)
-            self._send_command('CC_GET_CCD_INFO', params=ccd_info_params6, results=ccd_info_results6)
+            self._send_command(
+                'CC_GET_CCD_INFO',
+                params=ccd_info_params0,
+                results=ccd_info_results0)
+            self._send_command(
+                'CC_GET_CCD_INFO',
+                params=ccd_info_params2,
+                results=ccd_info_results2)
+            self._send_command(
+                'CC_GET_CCD_INFO',
+                params=ccd_info_params4,
+                results=ccd_info_results4)
+            self._send_command(
+                'CC_GET_CCD_INFO',
+                params=ccd_info_params6,
+                results=ccd_info_results6)
 
         # Now to convert all this ctypes stuff into Pythonic data structures.
         ccd_info = {'firmware_version': self._bcd_to_string(ccd_info_results0.firmwareVersion),
@@ -431,7 +463,8 @@ def _get_ccd_info(self, handle):
                     'colour': bool(ccd_info_results6.ccd_b0),
                     'Truesense': bool(ccd_info_results6.ccd_b1)}
 
-        readout_mode_info = self._parse_readout_info(ccd_info_results0.readoutInfo[0:ccd_info_results0.readoutModes])
+        readout_mode_info = self._parse_readout_info(
+            ccd_info_results0.readoutInfo[0:ccd_info_results0.readoutModes])
         ccd_info['readout_modes'] = readout_mode_info
 
         return ccd_info
@@ -499,7 +532,8 @@ def _disable_vdd_optimized(self, handle):
         of altering the bias structure between short and long exposures. This could cause systematic errors in bias
         frames, dark current measurements, etc. It's probably not worth it.
         """
-        set_driver_control_params = SetDriverControlParams(driver_control_codes['DCP_VDD_OPTIMIZED'], 0)
+        set_driver_control_params = SetDriverControlParams(
+            driver_control_codes['DCP_VDD_OPTIMIZED'], 0)
         self.logger.debug('Disabling DCP_VDD_OPTIMIZE on {}'.format(handle))
         with self._command_lock:
             self._set_handle(handle)
@@ -884,7 +918,9 @@ class QueryTemperatureStatusResults2(ctypes.Structure):
                            5: "REGULATION_ENABLE_AUTOFREEZE",
                            6: "REGULATION_DISABLE_AUTOFREEZE"}
 
-temperature_regulation_codes = {regulation: code for code, regulation in temperature_regulations.items()}
+temperature_regulation_codes = {
+    regulation: code for code,
+    regulation in temperature_regulations.items()}
 
 
 class SetTemperatureRegulationParams(ctypes.Structure):

pocs/camera/simulator.py

@@ -99,7 +99,9 @@ def take_exposure(self, seconds=1.0 * u.second, filename=None, dark=False, block
             seconds = seconds.to(u.second)
             seconds = seconds.value
 
-        self.logger.debug('Taking {} second exposure on {}: {}'.format(seconds, self.name, filename))
+        self.logger.debug(
+            'Taking {} second exposure on {}: {}'.format(
+                seconds, self.name, filename))
 
         # Set up a Timer that will wait for the duration of the exposure then copy a dummy FITS file
         # to the specified path and adjust the headers according to the exposure time, type.