Logging adjustments

* Timestamp and log level are no longer hard-coded in log messages - rather the
  default logger is configured with a formatter that includes them. An
  application that provides its own logger may choose its own format.

* Adjusted several log messages to use more appropriate levels (ERROR for
  errors, DEBUG for chatter).

Author: iain MacDonnell

CHANGELOG.rst

@@ -16,22 +16,28 @@ _____
 * If a delegation token is being used for authorization the HTTP header,
   'opc-obo-token' will be sent with the contents of the token.
 * Rate Limiting (cloud only):
+
   * New method NoSQLHandleConfig.set_rate_limiting_enabled to enable automatic
     internal rate limiting based on table read and write throughput limits.
   * If rate limiting is enabled:
+
     * NoSQLHandleConfig.set_default_rate_limiting_percentage can control how
       much of a table's full limits this client handle can consume
       (default = 100%).
     * Result classes now have a Result.get_rate_limit_delayed_ms method to
       return the amount of time an operation was delayed due to internal rate
       limiting.
+
   * Add rate limiting example and test.
+
 * RetryStats: New object allows the application to see how much time and for
   what reasons an operation was internally retried.
+
   * For successful operations, retry stats can be retrieved using
     Result.get_retry_stats.
   * Otherwise, the original Request may have retry stats available via
     Request.get_retry_stats (for example, after an exception was thrown).
+
 * Cloud only: New regions: ap-chiyoda-1, me-dubai-1, sa-santiago-1 and
   uk-cardiff-1.
 * Added dependency on dateutil package for flexible timestamp handling
@@ -49,15 +55,20 @@ _______
 * Enhance handling of TIMESTAMP types to better handle a datetime instance with
   an explicit timezone. By default fields of type TIMESTAMP returned by the system
   are represented by a  "naive" (not timezone aware) datetime object in the timezone UTC.
+* Timestamp and log level are no longer hard-coded in log messages - rather the
+  default logger is configured with a formatter that includes them. An application
+  that provides its own logger may choose its own format.
+* Adjusted several log messages to use more appropriate levels (ERROR for errors,
+  DEBUG for chatter).
 
 Fixed
 _____
 
 * Ensure that TableLimits is always None in TableResult on-premise.
 * Fixed synchronization problem in SignatureProvider.
 * Fixed a problem where the cloud service might succeed when dropping a table
-that does not exist without using "drop table if exists" when it should throw
-TableNotFoundException
+  that does not exist without using "drop table if exists" when it should throw
+  TableNotFoundException
 
 Removed
 _______
@@ -85,6 +96,7 @@ _____
   CA_MONTREAL_1, EU_AMSTERDAM_1, ME_JEDDAH_1.
 * Cloud only. Added support for authenticating via Resource Principal. This can
   be used in Oracle Cloud Functions to access NoSQL cloud service:
+
   * Added a new method SignatureProvider.create_with_resource_principal.
   * Added a new method SignatureProvider.get_resource_principal_claim to
     retrieve resource principal metadata with ResourcePrincipalClaimKeys such as

src/borneo/client.py

@@ -75,13 +75,13 @@ def __init__(self, config, logger):
         # StoreAccessTokenProvider means onprem
         if (config.get_rate_limiting_enabled() and
                 not isinstance(self._auth_provider, StoreAccessTokenProvider)):
-            self._logutils.log_info(
-                'Starting client with rate limiting enabled.')
+            self._logutils.log_debug(
+                'Starting client with rate limiting enabled')
             self._rate_limiter_map = RateLimiterMap()
             self._table_limit_update_map = dict()
             self._threadpool = pool.ThreadPool(1)
         else:
-            self._logutils.log_info('Starting client with no rate limiting.')
+            self._logutils.log_debug('Starting client with no rate limiting')
             self._rate_limiter_map = None
             self._table_limit_update_map = None
             self._threadpool = None
@@ -242,7 +242,7 @@ def set_ratelimiter_duration_seconds(self, duration_seconds):
 
     def shut_down(self):
         # Shutdown the client.
-        self._logutils.log_info('Shutting down driver http client')
+        self._logutils.log_debug('Shutting down driver http client')
         if self._shut_down:
             return
         self._shut_down = True
@@ -369,24 +369,24 @@ def _update_table_limiters(self, table_name):
         req = GetTableRequest().set_table_name(table_name).set_timeout(1000)
         res = None
         try:
-            self._logutils.log_info(
+            self._logutils.log_debug(
                 'Starting GetTableRequest for table "' + table_name + '"')
             res = self.execute(req)
         except Exception as e:
-            self._logutils.log_info(
+            self._logutils.log_error(
                 'GetTableRequest for table "' + table_name +
                 '" returned exception: ' + str(e))
         if res is None:
             # table doesn't exist? other error?
-            self._logutils.log_info(
+            self._logutils.log_error(
                 'GetTableRequest for table "' + table_name + '" returned None')
             then = self._table_limit_update_map.get(table_name)
             if then is not None:
                 # Allow retry after 100ms.
                 self._table_limit_update_map[table_name] = (
                     int(round(time() * 1000000000)) + 100000000)
             return
-        self._logutils.log_info(
+        self._logutils.log_debug(
             'GetTableRequest completed for table "' + table_name + '"')
         # Update/add rate limiters for table.
         if self.update_rate_limiters(table_name, res.get_table_limits()):

src/borneo/common.py

@@ -530,23 +530,23 @@ def __init__(self, logger=None):
 
     def log_critical(self, msg):
         if self._logger is not None:
-            self._logger.critical(ctime() + '[CRITICAL]' + msg)
+            self._logger.critical(msg)
 
     def log_error(self, msg):
         if self._logger is not None:
-            self._logger.error(ctime() + '[ERROR]' + msg)
+            self._logger.error(msg)
 
     def log_warning(self, msg):
         if self._logger is not None:
-            self._logger.warning(ctime() + '[WARNING]' + msg)
+            self._logger.warning(msg)
 
     def log_info(self, msg):
         if self._logger is not None:
-            self._logger.info(ctime() + '[INFO]' + msg)
+            self._logger.info(msg)
 
     def log_debug(self, msg):
         if self._logger is not None:
-            self._logger.debug(ctime() + '[DEBUG]' + msg)
+            self._logger.debug(msg)
 
     def is_enabled_for(self, level):
         return self._logger is not None and self._logger.isEnabledFor(level)

src/borneo/driver.py

@@ -6,7 +6,7 @@
 #
 
 from json import loads
-from logging import FileHandler, WARNING, getLogger
+from logging import FileHandler, Formatter, WARNING, getLogger
 from os import mkdir, path
 from ssl import SSLContext, SSLError, create_default_context
 from sys import argv
@@ -671,7 +671,10 @@ def _get_logger(self, config):
             log_dir = path.join(path.abspath(path.dirname(argv[0])), 'logs')
             if not path.exists(log_dir):
                 mkdir(log_dir)
-            logger.addHandler(FileHandler(path.join(log_dir, 'driver.log')))
+            handler = FileHandler(path.join(log_dir, 'driver.log'))
+            formatter = Formatter('%(asctime)s [%(levelname)s] %(message)s')
+            handler.setFormatter(formatter)
+            logger.addHandler(handler)
         else:
             logger = config.get_logger()
         return logger

src/borneo/http.py

@@ -319,7 +319,7 @@ def _do_request(self, method, uri, headers, payload, timeout_ms):
                     self._request.increment_retries()
                     exception = ae
                     continue
-                self._logutils.log_info(
+                self._logutils.log_error(
                     'Unexpected authentication exception: ' + str(ae))
                 raise NoSQLException('Unexpected exception: ' + str(ae), ae)
             except SecurityInfoNotReadyException as se:
@@ -460,7 +460,7 @@ def _handle_retry(self, re, request):
     def _log_retried(self, num_retried, exception):
         msg = ('Client, doing retry: ' + str(num_retried) +
                ('' if exception is None else ', exception: ' + str(exception)))
-        self._logutils.log_info(msg)
+        self._logutils.log_debug(msg)
 
     @synchronized
     def _next_request_id(self):

src/borneo/iam/iam.py

@@ -398,7 +398,7 @@ def _refresh_task(self):
             # Ignore the failure of refresh. The driver would try to generate
             # signature in the next request if signature is not available, the
             # failure would be reported at that moment.
-            self._logutils.log_warning(
+            self._logutils.log_debug(
                 'Unable to refresh cached request signature, ' + str(e))
             self._timer.cancel()
             self._timer = None

src/borneo/kv/kv.py

@@ -155,11 +155,11 @@ def close(self):
             response = self._send_request(
                 self._auth_string, StoreAccessTokenProvider._LOGOUT_SERVICE)
             if response.get_status_code() != codes.ok:
-                self._logutils.log_info(
+                self._logutils.log_error(
                     'Failed to logout user ' + self._user_name + ': ' +
                     response.get_content())
         except Exception as e:
-            self._logutils.log_info(
+            self._logutils.log_error(
                 'Failed to logout user ' + self._user_name + ': ' + str(e))
 
         # Clean up.
@@ -301,7 +301,7 @@ def _refresh_task(self):
                         StoreAccessTokenProvider._BEARER_PREFIX + token)
             self._schedule_refresh()
         except Exception as e:
-            self._logutils.log_info('Failed to renew login token: ' + str(e))
+            self._logutils.log_error('Failed to renew login token: ' + str(e))
             if self._timer is not None:
                 self._timer.cancel()
                 self._timer = None