Logging updates #254

wtgee · 2017-12-27T01:44:51Z

Replace PanLogger with custom LogRecord class
- Allow logger to use either % or {} (str.format) style for actual
  log messages.
Log messages show correct file/lineno
Add timezone info to log line
Reorder log.yaml

Fixes #253

Now you can:

pocs.logger.debug("Hello {}", 42)        # Hello 42
pocs.logger.debug("Hello {:.02f}", 42)   # Hello 42.00
pocs.logger.debug("Hello %f", 42)        # Hello 42.00000
pocs.logger.debug("Hello {:.02f}%", 42)  # Hello 42.00%
pocs.logger.debug("Hello {:.02f}%f", 42) # Hello {:.02f}42.000000 - See below

For the last example we could double-interpolate it, but I don't think it is too large of an issue.

Note that this performs legacy interpolation first (via %) and catches exceptions and then tries the str.format. Might be more efficient to reverse order but I don't think the impact is large.

Full log output example:

MainProcess(19834) MainThread 20171227015442GMT INFO     messaging.py        : 122:send_message              PANCHAT Hi there!

* Replace PanLogger with custom `LogRecord` class * Allow logger to use either `%` or `{}` (str.format) style for actual log messages. * Log messages show correct file/lineno * Reorder log.yaml Fixes panoptes#253

codecov · 2017-12-27T02:16:29Z

Codecov Report

Merging #254 into develop will decrease coverage by 0.02%.
The diff coverage is 100%.

@@             Coverage Diff             @@
##           develop     #254      +/-   ##
===========================================
- Coverage    79.36%   79.34%   -0.03%     
===========================================
  Files           46       46              
  Lines         3238     3229       -9     
  Branches       425      424       -1     
===========================================
- Hits          2570     2562       -8     
+ Misses         521      520       -1     
  Partials       147      147

Impacted Files	Coverage Δ
pocs/utils/messaging.py	`75.25% <100%> (ø)`	⬆️
pocs/utils/logger.py	`96.49% <100%> (+1.03%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 9c23179...eac4066. Read the comment docs.

jamessynge

Thanks so much. A few nits, but otherwise LGTM.

jamessynge · 2017-12-27T18:46:43Z

conf_files/log.yaml

-        handlers: [error]
-        propagate: true        
-
+        style: '{'


FWIW, I'd like to experiment (myself) with having separate loggers for each process, which would shorten the length of the lines. In addition, I'd like to examine the possibility of logging the thread id (a number) rather than the potentially very long thread name. Basically, I'd like to get the length of the fixed portion down so that we'd have something like:

E1217 01:23:45.679 02420 messaging.py:123

The first char is a level indicator, e.g. first letter of Fatal, Critical, Error, Warning, Info, Debug.
Then 4 digits for the date in the year (MMDD).
Next a space separator, then the time of day, down to the milliseconds.
After that a thread id (fixed length, e.g. 5 digits, with leading zeros or spaces).
Finally the source of the message (variable length) and the message.

Yes, good idea. My next step was to reduce the fixed portion and I like this suggestion.

One note, I did originally add the thread ID in but it was giving me a 12 digit string, which seemed odd. I'll play a little more.

Confirmed, the thread id is a very large number. Current format with latest commit is:

I1228 10:05:01.572 logger.py:112 ****************************** Starting PanLogger ****************************** I1228 10:05:04.897 observatory.py:35 Initializing observatory I1228 10:05:04.897 observatory.py:38 Setting up location D1228 10:05:04.897 observatory.py:483 Setting up site details of observatory

Note that we lose time zone information by adding the msecs. Could get back in there with a little bit of work but not entirely sure how important it is.

jamessynge · 2017-12-27T18:46:56Z

conf_files/log.yaml

@@ -3,26 +3,12 @@ logger:
    use_utc: True
    formatters:
      simple:
-        format: '%(asctime)s UTC - %(message)s'
+        format: '%(asctime)s - %(message)s'


Thanks for removing UTC

jamessynge · 2017-12-27T18:49:57Z

pocs/utils/logger.py

-    def critical(self, fmt, *args, **kwargs):
-        self.logger.critical(self._process_str(fmt, *args, **kwargs))
+    Even though you can select '{' as the style for the formatter class,
+    you still can't use {} formatting for your message. The custom


Apparently I was totally incorrect when I claimed that Python could handle this. I followed your link and found this comment:

Your statement about Python 3 is incorrect. The style parameter only applies to the Formatter format string, not the individual log messages. The page you linked to explicitly says: "There would no changing this while preserving backward compatibility".

So apparently many folks have misinterpreted the description of the style parameter as applying to the formatting of the log messages, not of the line that will contain the log message. Sigh.

My apologies for sending you down the wrong path, and my gratitude that you found your way to a superior solution.

No worries, I'm glad you suggested it as it forced me to dig up the correct method. I think the documents are very confusing in terms of what it allows. Honestly, I was very surprised there wasn't an existing module that would just do this, but I couldn't find anything.

And the incorrect file and line number was really starting to bother me, so it was a good time for it.

jamessynge · 2017-12-27T19:40:11Z

pocs/utils/logger.py

+                msg = msg % self.args
+            except (TypeError, ValueError):
+                msg = msg.format(*self.args)
+        return msg


 def get_root_logger(profile='panoptes', log_config=None):


Please document params, especially point to https://docs.python.org/3/library/logging.config.html#configuration-dictionary-schema to explain log_config.

jamessynge · 2017-12-27T19:43:20Z

pocs/utils/logger.py

@@ -87,11 +70,11 @@ def get_root_logger(profile='panoptes', log_config=None):
        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
+        # Setup the TimedRotatingFileHandler for middle of day


A TODO for the future: remove explicit reference to TimedRotatingFileHandler, and instead check for atTime being a string in the log_config, and if so parsing it with some flexibility regarding the time format.

Not sure I understand what that would get us but let's discuss in a separate Issue.

jamessynge · 2017-12-27T19:50:43Z

pocs/utils/logger.py

        log_config['handlers'][handler].setdefault('atTime', datetime.time(hour=11, minute=30))

        if handler == 'all':
-            # Symlink the log file to $PANDIR/logs/panoptes.log
+            # Symlink the log file to log_symlink


I think of this as the other way around:

# Create a symlink to the log file with just the name of the script, not the date and pid, # as this makes it easier to find the latest such log file when debugging.

* Reduced log message format via filter (see example below) * Add docstring * Fix logger on messaging * Remove unused coloredlogs module (will put `grc` info in wiki) ``` I1228 10:05:01.572 logger.py:112 ****************************** Starting PanLogger ****************************** I1228 10:05:04.897 observatory.py:35 Initializing observatory I1228 10:05:04.897 observatory.py:38 Setting up location D1228 10:05:04.897 observatory.py:483 Setting up site details of observatory ```

Logging updates

df8c5be

* Replace PanLogger with custom `LogRecord` class * Allow logger to use either `%` or `{}` (str.format) style for actual log messages. * Log messages show correct file/lineno * Reorder log.yaml Fixes panoptes#253

wtgee requested a review from jamessynge December 27, 2017 01:44

Update docstring

5a66f60

wtgee mentioned this pull request Dec 27, 2017

Remove PanLogger class #253

Closed

jamessynge approved these changes Dec 27, 2017

View reviewed changes

wtgee added 2 commits December 28, 2017 21:07

Adding no cover pragma

eac4066

wtgee merged commit 8a973d0 into panoptes:develop Dec 28, 2017

wtgee deleted the logging-updates branch December 28, 2017 23:21

This was referenced Dec 29, 2017

Move polar alignment helper functions into POCS images utils #265

Merged

Release 0.6.0 #271

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging updates #254

Logging updates #254

wtgee commented Dec 27, 2017 •

edited

Loading

codecov bot commented Dec 27, 2017 •

edited

Loading

jamessynge left a comment

jamessynge Dec 27, 2017

wtgee Dec 28, 2017

wtgee Dec 28, 2017

jamessynge Dec 27, 2017

jamessynge Dec 27, 2017

wtgee Dec 28, 2017

jamessynge Dec 27, 2017

jamessynge Dec 27, 2017

wtgee Dec 28, 2017

jamessynge Dec 27, 2017

Logging updates #254

Logging updates #254

Conversation

wtgee commented Dec 27, 2017 • edited Loading

codecov bot commented Dec 27, 2017 • edited Loading

Codecov Report

jamessynge left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wtgee commented Dec 27, 2017 •

edited

Loading

codecov bot commented Dec 27, 2017 •

edited

Loading