Add logging

Author: awarecan

.gitignore

@@ -40,4 +40,7 @@ nosetests.xml
 MANIFEST
 
 # PyCharm
-.idea/*
+.idea
+
+# VS Code
+.vscode

README.rst

@@ -223,14 +223,14 @@ Command line
 
     usage: nest [-h] [--conf FILE] [--token-cache TOKEN_CACHE_FILE] [-t TOKEN]
                 [--client-id ID] [--client-secret SECRET] [-k] [-c] [-s SERIAL]
-                [-S STRUCTURE] [-i INDEX]
+                [-S STRUCTURE] [-i INDEX] [-v]
                 {temp,fan,mode,away,target,humid,target_hum,show,camera-show,camera-streaming,protect-show}
                 ...
 
     Command line interface to Nest™ Thermostats
 
     positional arguments:
-    {temp,fan,mode,away,target,humid,target_hum,show,camera-show,camera-streaming,protect-show}
+      {temp,fan,mode,away,target,humid,target_hum,show,camera-show,camera-streaming,protect-show}
                             command help
         temp                show/set temperature
         fan                 set fan "on" or "auto"
@@ -265,6 +265,7 @@ Command line
                             actions
       -i INDEX, --index INDEX
                             optional, specify index number of nest to talk to
+      -v, --verbose         showing verbose logging
 
     examples:
         # If your nest is not in range mode

nest/__init__.py

@@ -1,8 +1,11 @@
 # -*- coding:utf-8 -*-
+import logging
 
 from .nest import Nest
 
 from .utils import CELSIUS
 from .utils import FAHRENHEIT
 
+logging.getLogger(__name__).addHandler(logging.NullHandler())
+
 __all__ = ['CELSIUS', 'FAHRENHEIT', 'Nest']

nest/command_line.py

@@ -9,6 +9,7 @@
 
 import argparse
 import datetime
+import logging
 import os
 import sys
 import errno
@@ -76,6 +77,10 @@ def get_parser():
                         help='optional, specify index number of nest to '
                              'talk to')
 
+    parser.add_argument('-v', '--verbose', dest='verbose',
+                        action='store_true',
+                        help='showing verbose logging')
+
     subparsers = parser.add_subparsers(dest='command',
                                        help='command help')
     temp = subparsers.add_parser('temp', help='show/set temperature')
@@ -298,6 +303,17 @@ def main():
     parser = get_parser()
     args = parser.parse_args()
 
+    if args.verbose:
+        logger = logging.getLogger('nest')
+        logger.setLevel(logging.DEBUG)
+        console_handler = logging.StreamHandler()
+        formatter = logging.Formatter(
+           "%(asctime)s %(levelname)s (%(threadName)s) "
+           "[%(name)s] %(message)s", datefmt="%Y-%m-%d %H:%M:%S")
+        console_handler.setFormatter(formatter)
+        console_handler.setLevel(logging.DEBUG)
+        logger.addHandler(console_handler)
+
     # This is the command(s) passed to the command line utility
     cmd = args.command
     if cmd is None:

nest/nest.py

@@ -4,6 +4,7 @@
 import copy
 import datetime
 import hashlib
+import logging
 import threading
 import time
 import os
@@ -62,6 +63,8 @@
 MINIMUM_TEMPERATURE_C = 9
 MAXIMUM_TEMPERATURE_C = 32
 
+_LOGGER = logging.getLogger(__name__)
+
 
 class APIError(Exception):
     def __init__(self, response, msg=None):
@@ -131,6 +134,8 @@ def __init__(self, auth_callback=None, session=None,
                 access_token is None and
                 os.path.exists(access_token_cache_file)):
             with open(access_token_cache_file, 'r') as f:
+                _LOGGER.debug("Load access token from %s",
+                              access_token_cache_file)
                 self._res = json.load(f)
                 self._callback(self._res)
 
@@ -145,6 +150,8 @@ def _cache(self):
             with os.fdopen(os.open(self._access_token_cache_file,
                                    os.O_WRONLY | os.O_CREAT, 0o600),
                            'w') as f:
+                _LOGGER.debug("Save access token to %s",
+                              self._access_token_cache_file)
                 json.dump(self._res, f)
 
     def _callback(self, res):
@@ -164,7 +171,9 @@ def login(self, headers=None):
             session = self._session()
             post = session.post
 
+        _LOGGER.debug(">> POST %s", ACCESS_TOKEN_URL)
         response = post(ACCESS_TOKEN_URL, data=data, headers=headers)
+        _LOGGER.debug("<< %s", response.status_code)
         if response.status_code != 200:
             raise AuthorizationError(response)
         self._res = response.json()
@@ -1681,6 +1690,8 @@ def _handle_ratelimit(self, res, verb, url, data,
         while response.status_code == 429 and retries <= max_retries:
             retries += 1
             retry_after = response.headers['Retry-After']
+            _LOGGER.info("Reach rate limit, retry (%d), after %s",
+                         retries, retry_after)
             # Default Retry Time
             wait = default_wait
 
@@ -1697,22 +1708,27 @@ def _handle_ratelimit(self, res, verb, url, data,
                     # Does nothing and uses default (shouldn't happen)
                     pass
 
+            _LOGGER.debug("Wait %d seconds.", wait)
             time.sleep(wait)
+            _LOGGER.debug(">> %s %s", 'STREAM' if stream else verb, url)
             response = self._session.request(verb, url,
                                              allow_redirects=False,
                                              stream=stream,
                                              headers=headers,
                                              data=data)
+            _LOGGER.debug("<< %s", response.status_code)
         return response
 
     def _open_data_stream(self, path="/"):
         url = "%s%s" % (API_URL, path)
+        _LOGGER.debug(">> STREAM %s", url)
 
         # Opens the data stream
         headers = {'Accept': 'text/event-stream'}
         response = self._session.get(url, stream=True, headers=headers,
                                      allow_redirects=False)
 
+        _LOGGER.debug("<< %s", response.status_code)
         if response.status_code == 401:
             raise AuthorizationError(response)
 
@@ -1725,10 +1741,12 @@ def _open_data_stream(self, path="/"):
 
         if response.status_code == 307:
             redirect_url = response.headers['Location']
+            _LOGGER.debug(">> STREAM %s", redirect_url)
             response = self._session.get(redirect_url,
                                          allow_redirects=False,
                                          headers=headers,
                                          stream=True)
+            _LOGGER.debug("<< %s", response.status_code)
             if response.status_code == 429:
                 response = self._handle_ratelimit(response, 'GET', url, None,
                                                   max_retries=10,
@@ -1745,12 +1763,15 @@ def _open_data_stream(self, path="/"):
         self._event_thread.setDaemon(True)
         self._event_thread.start()
         ready_event.wait(timeout=10)
+        _LOGGER.info("Event loop started.")
 
     def _start_event_loop(self, response, queue, ready_event, update_event):
+        _LOGGER.debug("Starting event loop.")
         try:
             client = sseclient.SSEClient(response.iter_content())
             for event in client.events():
                 event_type = event.event
+                _LOGGER.debug("<<< %s event", event_type)
                 if event_type == 'open' or event_type == 'keep-alive':
                     pass
                 elif event_type == 'put':
@@ -1765,22 +1786,26 @@ def _start_event_loop(self, response, queue, ready_event, update_event):
                 if not ready_event.is_set():
                     ready_event.set()
         finally:
+            _LOGGER.debug("Stopping event loop.")
             queue.clear()
             update_event.set()
             try:
                 response.close()
             except Exception:
                 pass
+            _LOGGER.info("Event loop stopped.")
 
     def _request(self, verb, path="/", data=None):
         url = "%s%s" % (API_URL, path)
+        _LOGGER.debug(">> %s %s", verb, url)
 
         if data is not None:
             data = json.dumps(data)
 
         response = self._session.request(verb, url,
                                          allow_redirects=False,
                                          data=data)
+        _LOGGER.debug("<< %s", response.status_code)
         if response.status_code == 200:
             return response.json()
 
@@ -1802,10 +1827,12 @@ def _request(self, verb, path="/", data=None):
             raise APIError(response)
 
         redirect_url = response.headers['Location']
+        _LOGGER.debug(">> %s %s", verb, redirect_url)
         response = self._session.request(verb, redirect_url,
                                          allow_redirects=False,
                                          data=data)
 
+        _LOGGER.debug("<< %s", response.status_code)
         # Rate Limit Exceeded Catch
         if response.status_code == 429:
             response = self._handle_ratelimit(response, verb, redirect_url,
@@ -1835,6 +1862,7 @@ def _status(self):
         self._queue_lock.acquire()
         if len(self._queue) == 0 or not self._queue[0]:
             try:
+                _LOGGER.info("Open data stream")
                 self._open_data_stream("/")
             except AuthorizationError as authorization_error:
                 self._queue_lock.release()
@@ -1847,6 +1875,7 @@ def _status(self):
         value = self._queue[0]['data'] if len(self._queue) > 0 else None
         if value is None:
             # fall back to pull mode
+            _LOGGER.info("Fall back to pull mode")
             value = self._get("/")
 
         return value