Log files updates

CONTRIBUTING.md

@@ -1,43 +1,111 @@
 # Getting Started
-If you are unsure about a possible contribution to the project contact the project owners about your idea.
+If you are unsure about a possible contribution to the project contact the project owners about 
+your idea.
 
-Please see the [code of conduct](https://github.com/panoptes/POCS/blob/develop/CODE_OF_CONDUCT.md) for our
+Please see the [code of conduct](https://github.com/panoptes/POCS/blob/develop/CODE_OF_CONDUCT.md) 
+for our
 playground rules and follow them during all your contributions.
 
 
 # Pull Request Process
 * Pre-requisites
    - Ensure you have [github account](https://github.com/join)
-   - If the change you wish to make is not already an Issue in the project please create one specifying the need.
+   - If the change you wish to make is not already an Issue in the project please create one 
+   specifying the need.
 * Process
    - Create a fork of the repository and use a topic branch within your fork to make changes.
-      - All of our repositories have a default branch of `develop` when you first clone them, but your work should be in a separate branch.
+      - All of our repositories have a default branch of `develop` when you first clone them, but 
+      your work should be in a separate branch.
       - Create a branch with a descriptive name, e.g.:
          - `git checkout -b new-camera-simulator`
          - `git checkout -b issue-28`
    - Ensure that your code meets this project's standards (see Testing and Code Formatting below).
          - Run `python setup.py test` from the `$POCS` directory before pushing to github
    - Squash your commits so they only reflect meaningful changes.
-   - Submit a pull request to the repository, be sure to reference the issue number it addresses.
+   - Submit a pull request to the repository, be sure to reference the issue number it 
+      addresses.
 
 
 # Setting up Local Environment
-  - Follow instructions on the [Coding in PANOPTES](https://github.com/panoptes/POCS/wiki/Coding-in-PANOPTES).
+  - Follow instructions in the [README](https://github.com/panoptes/POCS/blob/develop/README.md) 
+    as well as the [Coding in PANOPTES](https://github.com/panoptes/POCS/wiki/Coding-in-PANOPTES) 
+    document.
 
 
 # Testing
- - All changes should have corresponding tests and existing tests should pass after your changes.
- - For more on testing see the [Coding in PANOPTES](https://github.com/panoptes/POCS/wiki/Coding-in-PANOPTES) page.
+ - All changes should have corresponding tests and existing tests should pass after 
+    your changes.
+ - For more on testing see the 
+ [Coding in PANOPTES](https://github.com/panoptes/POCS/wiki/Coding-in-PANOPTES) page.
 
 
 # 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 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.
+
+# 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 available on the main `POCS` class 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>

Changelog.md

@@ -1,6 +1,8 @@
 ## [Unreleased]
+=======
 ### Added
 - Merge PACE into POCS
+- Logs: separate files for each level and new naming scheme
 
 ## [0.5.1] - 2017-12-02
 ### Added

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/core.py

@@ -25,7 +25,8 @@ class POCS(PanStateMachine, PanBase):
     the `get_ready()` method the transition that is responsible for moving to the initial state.
 
     Args:
-        state_machine_file(str): Filename of the state machine to use, defaults to 'simple_state_table'
+        state_machine_file(str): Filename of the state machine to use, defaults to
+            'simple_state_table'
         messaging(bool): If messaging should be included, defaults to False
         simulator(list): A list of the different modules that can run in simulator mode. Possible
             modules include: all, mount, camera, weather, night. Defaults to an empty list.
@@ -42,7 +43,11 @@ def __init__(self, state_machine_file='simple_state_table', messaging=False, **k
         # Explicitly call the base classes in the order we want
         PanBase.__init__(self, **kwargs)
 
-        self.logger.info('Initializing PANOPTES unit')
+        self.name = self.config.get('name', 'Generic PANOPTES Unit')
+        self.logger.info('Initializing PANOPTES unit - {} - {}',
+                         self.name,
+                         self.config['location']['name']
+                         )
 
         self._processes = {}
 
@@ -67,8 +72,6 @@ def __init__(self, state_machine_file='simple_state_table', messaging=False, **k
 
         self.status()
 
-        self.name = self.config.get('name', 'Generic PANOPTES Unit')
-        self.logger.info('Welcome {}!'.format(self.name))
         self.say("Hi there!")
 
     @property
@@ -377,7 +380,8 @@ def sleep(self, delay=2.5, with_status=True):
 
         Keyword Arguments:
             delay {float} -- Number of seconds to sleep (default: 2.5)
-            with_status {bool} -- Show system status while sleeping (default: {True if delay > 2.0})
+            with_status {bool} -- Show system status while sleeping
+                (default: {True if delay > 2.0})
         """
         if delay is None:
             delay = self._sleep_delay
@@ -482,7 +486,8 @@ def check_message_loop(cmd_queue):
                     # Poll for messages
                     sockets = dict(poller.poll(500))  # 500 ms timeout
 
-                    if cmd_subscriber.socket in sockets and sockets[cmd_subscriber.socket] == zmq.POLLIN:
+                    if cmd_subscriber.socket in sockets and \
+                            sockets[cmd_subscriber.socket] == zmq.POLLIN:
 
                         msg_type, msg_obj = cmd_subscriber.receive_message(flags=zmq.NOBLOCK)
 

pocs/images.py

@@ -31,7 +31,8 @@ def __init__(self, fits_file, wcs_file=None, location=None):
         if fits_file.endswith('.fz'):
             fits_file = img_utils.fpack(fits_file, unpack=True)
 
-        assert fits_file.lower().endswith(('.fits')), self.logger.warning('File must end with .fits')
+        assert fits_file.lower().endswith(('.fits')), \
+            self.logger.warning('File must end with .fits')
 
         self.wcs = None
         self._wcs_file = None
@@ -115,7 +116,8 @@ def pointing_error(self):
             namedtuple: Pointing error information
         """
         if self._pointing_error is None:
-            assert self.pointing is not None, self.logger.warn("No WCS, can't get pointing_error")
+            assert self.pointing is not None, self.logger.warning(
+                "No world coordinate system (WCS), can't get pointing_error")
             assert self.header_pointing is not None
 
             if self.wcs is None:

pocs/mount/bisque.py

@@ -124,7 +124,7 @@ def set_target_coordinates(self, coords):
         target_set = False
 
         if self.is_parked:
-            self.logger.warning("Mount is parked")
+            self.logger.info("Mount is parked")
         else:
             # Save the skycoord coordinates
             self.logger.debug("Setting target coordinates: {}".format(coords))
@@ -173,9 +173,9 @@ def slew_to_target(self):
         success = False
 
         if self.is_parked:
-            self.logger.warning("Mount is parked")
+            self.logger.info("Mount is parked")
         elif self._target_coordinates is None:
-            self.logger.warning("Target Coordinates not set")
+            self.logger.info("Target Coordinates not set")
         else:
             # Get coordinate format from mount specific class
             mount_coords = self._skycoord_to_mount_coord(self._target_coordinates)

pocs/mount/mount.py

@@ -358,9 +358,9 @@ def slew_to_target(self):
         success = False
 
         if self.is_parked:
-            self.logger.warning("Mount is parked")
+            self.logger.info("Mount is parked")
         elif not self.has_target:
-            self.logger.warning("Target Coordinates not set")
+            self.logger.info("Target Coordinates not set")
         else:
             success = self.query('slew_to_target')
 

pocs/utils/logger.py

@@ -1,16 +1,43 @@
+import os
+import sys
+import time
 import datetime
 import logging
 import logging.config
-import os
-import time
-
+from tempfile import gettempdir
 
 from .config import load_config
 
 
+class PanLogger(object):
+    """ Logger for PANOPTES with format style strings """
+
+    def __init__(self, logger):
+        super(PanLogger, self).__init__()
+        self.logger = logger
+
+    def _process_str(self, fmt, *args, **kwargs):
+        log_str = fmt
+        if len(args) > 0 or len(kwargs) > 0:
+            log_str = fmt.format(*args, **kwargs)
+
+        return log_str
+
+    def debug(self, fmt, *args, **kwargs):
+        self.logger.debug(self._process_str(fmt, *args, **kwargs))
+
+    def info(self, fmt, *args, **kwargs):
+        self.logger.info(self._process_str(fmt, *args, **kwargs))
+
+    def warning(self, fmt, *args, **kwargs):
+        self.logger.warning(self._process_str(fmt, *args, **kwargs))
+
+    def error(self, fmt, *args, **kwargs):
+        self.logger.error(self._process_str(fmt, *args, **kwargs))
+
+
 def get_root_logger(profile='panoptes', log_config=None):
     """ Creates a root logger for PANOPTES used by the PanBase object
-
     Returns:
         logger(logging.logger): A configured instance of the logger
     """
@@ -23,23 +50,41 @@ def get_root_logger(profile='panoptes', log_config=None):
         for name, formatter in log_config['formatters'].items():
             log_config['formatters'][name].setdefault('()', _UTCFormatter)
 
-    log_file_lookup = {
-        'all': "{}/logs/panoptes.log".format(os.getenv('PANDIR', '/var/panoptes')),
-        'warn': "{}/logs/warnings.log".format(os.getenv('PANDIR', '/var/panoptes')),
-    }
+        log_fname_datetime = datetime.datetime.utcnow().strftime('%Y%m%dT%H%M%SZ')
+    else:
+        log_fname_datetime = datetime.datetime.now().strftime('%Y%m%dT%H%M%SZ')
+
+    # Setup log file names
+    invoked_script = os.path.basename(sys.argv[0])
+    log_dir = '{}/logs'.format(os.getenv('PANDIR', gettempdir()))
+    log_fname = '{}-{}-{}'.format(invoked_script, os.getpid(), log_fname_datetime)
+    log_symlink = '{}/{}.log'.format(log_dir, invoked_script)
 
-    # Setup the TimeedRotatingFileHandler to backup in middle of day intead of middle of night
+    # Set log filename and rotation
     for handler in log_config.get('handlers', []):
-        log_config['handlers'][handler].setdefault('filename', log_file_lookup[handler])
-        if handler in ['all', 'warn']:
-            log_config['handlers'][handler].setdefault('atTime', datetime.time(hour=11, minute=30))
+        # Set the filename
+        full_log_fname = '{}/{}-{}.log'.format(log_dir, log_fname, handler)
+        log_config['handlers'][handler].setdefault('filename', full_log_fname)
+
+        # Setup the TimeedRotatingFileHandler for middle of day
+        log_config['handlers'][handler].setdefault('atTime', datetime.time(hour=11, minute=30))
+
+        if handler == 'all':
+            # Symlink the log file to $PANDIR/logs/panoptes.log
+            try:
+                os.unlink(log_symlink)
+            except FileNotFoundError:
+                pass
+            finally:
+                os.symlink(full_log_fname, log_symlink)
 
     # Configure the logger
     logging.config.dictConfig(log_config)
 
     # Get the logger and set as attribute to class
     logger = logging.getLogger(profile)
 
+    # Don't want log messages from state machine library
     logging.getLogger('transitions.core').setLevel(logging.WARNING)
 
     try:
@@ -48,7 +93,7 @@ def get_root_logger(profile='panoptes', log_config=None):
     except Exception:  # pragma: no cover
         pass
 
-    return logger
+    return PanLogger(logger)
 
 
 class _UTCFormatter(logging.Formatter):