Issues/101: fix logging

CHANGELOG.md

@@ -1,6 +1,9 @@
 ## `naz` changelog:
 most recent version is listed first.
 
+## **version:** v0.6.1
+- all the changes in `v0.6.0-beta.1`
+- fix a number of logging issues: https://github.com/komuw/naz/pull/105
 
 ## **version:** v0.6.0-beta.1
 - Bug fix: https://github.com/komuw/naz/pull/98    

README.md

@@ -156,7 +156,7 @@ example usage: naz-cli --config /path/to/my_config.json
 optional arguments:
   -h, --help            show this help message and exit
   --version             The currently installed naz version.
-  --loglevel {DEBUG,INFO,WARNING,ERROR,CRITICAL}
+  --loglevel {NOTSET,DEBUG,INFO,WARNING,ERROR,CRITICAL}
                         The log level to output log messages at. eg: --loglevel DEBUG
   --config CONFIG       The config file to use. eg: --config /path/to/my_config.json
 ```

cli/cli.py

@@ -79,7 +79,7 @@ def make_parser():
         type=str,
         required=False,
         default="INFO",
-        choices=["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"],
+        choices=["NOTSET", "DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"],
         help="The log level to output log messages at. \
         eg: --loglevel DEBUG",
     )
@@ -106,7 +106,7 @@ def main():
     """
     """
     _client_id = "".join(random.choices(string.ascii_uppercase + string.digits, k=17))
-    logger = naz.logger.SimpleBaseLogger("naz.cli")
+    logger = naz.logger.SimpleLogger("naz.cli")
     logger.log(logging.INFO, {"event": "naz.cli.main", "stage": "start", "client_id": _client_id})
 
     loop = asyncio.get_event_loop()
@@ -137,7 +137,7 @@ def main():
                 "client_id": client_id,
             }
         )
-        logger.bind(loglevel=loglevel, log_metadata=log_metadata)
+        logger.bind(level=loglevel, log_metadata=log_metadata)
 
         logger.log(logging.INFO, "\n\n\t {} \n\n".format("Naz: the SMPP client."))
         if dry_run:

documentation/config.md

@@ -48,7 +48,7 @@ encoding | encoding<sup>1</sup> used to encode messages been sent to SMSC | gsm0
 sequence_generator | python class instance used to generate sequence_numbers| naz.sequence.SimpleSequenceGenerator
 outboundqueue | python class instance implementing some queueing mechanism. messages to be sent to SMSC are queued using the said mechanism before been sent | N/A
 client_id | a unique string identifying a naz client class instance | "".join(random.choices(string.ascii_uppercase + string.digits, k=17))   
-log_handler | python class instance to be used for logging | naz.logger.SimpleBaseLogger        
+log_handler | python class instance to be used for logging | naz.logger.SimpleLogger        
 loglevel | the level at which to log | DEBUG
 log_metadata | metadata that will be included in all log statements | {"smsc_host": smsc_host, "system_id": system_id}
 codec_class | python class instance to be used to encode/decode messages | naz.nazcodec.SimpleNazCodec

documentation/sphinx-docs/logger.rst

@@ -2,6 +2,6 @@ logger
 ---------------
 
 .. automodule:: naz.logger
-    :members: BaseLogger, SimpleBaseLogger
+    :members: BaseLogger, SimpleLogger
     :show-inheritance:
 

naz/__version__.py

@@ -2,7 +2,7 @@
     "__title__": "naz",
     "__description__": "Naz is an async SMPP client.",
     "__url__": "https://github.com/komuw/naz",
-    "__version__": "v0.6.0-beta.1",
+    "__version__": "v0.6.1",
     "__author__": "komuW",
     "__author_email__": "komuw05@gmail.com",
     "__license__": "MIT",

naz/client.py

@@ -130,9 +130,9 @@ def __init__(
             correlation_handler: A python class instance that naz uses to store relations between \
                 SMPP sequence numbers and user applications' log_id's and/or hook_metadata.
         """
-        if loglevel.upper() not in ["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"]:
+        if loglevel.upper() not in ["NOTSET", "DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"]:
             raise ValueError(
-                """loglevel should be one of; 'DEBUG', 'INFO', 'WARNING', 'ERROR' or 'CRITICAL'. not {0}""".format(
+                """loglevel should be one of; 'NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR' or 'CRITICAL'. not {0}""".format(
                     loglevel
                 )
             )
@@ -213,11 +213,10 @@ def __init__(
         self.reader: typing.Any = None
         self.writer: typing.Any = None
 
-        # NB: currently, naz only uses to log levels; INFO and EXCEPTION
         self.logger = log_handler
         if not self.logger:
-            self.logger = logger.SimpleBaseLogger("naz.client")
-        self.logger.bind(loglevel=self.loglevel, log_metadata=self.log_metadata)
+            self.logger = logger.SimpleLogger("naz.client")
+        self.logger.bind(level=self.loglevel, log_metadata=self.log_metadata)
         self._sanity_check_logger()
 
         self.rateLimiter = rateLimiter
@@ -427,7 +426,7 @@ async def enquire_link(self, TESTING: bool = False) -> typing.Union[bytes, None]
 
             log_id = "".join(random.choices(string.ascii_lowercase + string.digits, k=17))
             self._log(
-                logging.INFO,
+                logging.DEBUG,
                 {
                     "event": "naz.Client.enquire_link",
                     "stage": "start",
@@ -490,7 +489,7 @@ async def enquire_link(self, TESTING: bool = False) -> typing.Union[bytes, None]
             # dont queue enquire_link in SimpleOutboundQueue since we dont want it to be behind 10k msgs etc
             await self.send_data(smpp_command=smpp_command, msg=full_pdu, log_id=log_id)
             self._log(
-                logging.INFO,
+                logging.DEBUG,
                 {
                     "event": "naz.Client.enquire_link",
                     "stage": "end",
@@ -512,7 +511,7 @@ async def enquire_link_resp(self, sequence_number: int) -> None:
         smpp_command = SmppCommand.ENQUIRE_LINK_RESP
         log_id = "".join(random.choices(string.ascii_lowercase + string.digits, k=17))
         self._log(
-            logging.INFO,
+            logging.DEBUG,
             {
                 "event": "naz.Client.enquire_link_resp",
                 "stage": "start",
@@ -552,7 +551,7 @@ async def enquire_link_resp(self, sequence_number: int) -> None:
                 },
             )
         self._log(
-            logging.INFO,
+            logging.DEBUG,
             {
                 "event": "naz.Client.enquire_link_resp",
                 "stage": "end",
@@ -776,7 +775,7 @@ async def build_submit_sm_pdu(
         """
         smpp_command = SmppCommand.SUBMIT_SM
         self._log(
-            logging.INFO,
+            logging.DEBUG,
             {
                 "event": "naz.Client.build_submit_sm_pdu",
                 "stage": "start",
@@ -872,7 +871,7 @@ async def build_submit_sm_pdu(
         header = struct.pack(">IIII", command_length, command_id, command_status, sequence_number)
         full_pdu = header + body
         self._log(
-            logging.INFO,
+            logging.DEBUG,
             {
                 "event": "naz.Client.build_submit_sm_pdu",
                 "stage": "end",

naz/hooks.py

@@ -55,7 +55,7 @@ def __init__(self, logger) -> None:
 
     async def request(self, smpp_command: str, log_id: str, hook_metadata: str) -> None:
         self.logger.log(
-            logging.INFO,
+            logging.NOTSET,
             {
                 "event": "naz.SimpleHook.request",
                 "stage": "start",
@@ -69,7 +69,7 @@ async def response(
         self, smpp_command: str, log_id: str, hook_metadata: str, smsc_response: "naz.CommandStatus"
     ) -> None:
         self.logger.log(
-            logging.INFO,
+            logging.NOTSET,
             {
                 "event": "naz.SimpleHook.response",
                 "stage": "start",

naz/logger.py

@@ -1,4 +1,5 @@
 import abc
+import time
 import typing
 import logging
 
@@ -14,7 +15,7 @@ class BaseLogger(abc.ABC):
     """
 
     @abc.abstractmethod
-    def bind(self, loglevel: str, log_metadata: dict) -> None:
+    def bind(self, level: typing.Union[str, int], log_metadata: dict) -> None:
         """
         called when a naz client is been instantiated so that the logger can be
         notified of loglevel & log_metadata that a user supplied to a naz client.
@@ -24,31 +25,31 @@ def bind(self, loglevel: str, log_metadata: dict) -> None:
             loglevel: logging level eg DEBUG
             log_metadata: log metadata that can be included in all log statements
         """
-        raise NotImplementedError("bind method must be implemented.")
+        raise NotImplementedError("`bind` method must be implemented.")
 
     @abc.abstractmethod
-    def log(self, level: int, log_data: dict) -> None:
+    def log(self, level: typing.Union[str, int], log_data: dict) -> None:
         """
         called by naz everytime it wants to log something.
 
         Parameters:
             level: logging level eg `logging.INFO`
             log_data: the message to log
         """
-        raise NotImplementedError("log method must be implemented.")
+        raise NotImplementedError("`log` method must be implemented.")
 
 
-class SimpleBaseLogger(BaseLogger):
+class SimpleLogger(BaseLogger):
     """
     This is an implementation of BaseLogger.
-    It implements a structured logger that renders logs in a json/dict like manner.
+    It implements a structured logger that renders logs as a dict.
 
     example usage:
 
     .. code-block:: python
 
-        logger = SimpleBaseLogger("myLogger")
-        logger.bind(loglevel="INFO",
+        logger = SimpleLogger("myLogger")
+        logger.bind(level="INFO",
                     log_metadata={"customer_id": "34541"})
         logger.log(logging.INFO,
                    {"event": "web_request", "url": "https://www.google.com/"})
@@ -57,35 +58,81 @@ class SimpleBaseLogger(BaseLogger):
     def __init__(self, logger_name: str):
         """
         Parameters:
-            logger_name: name of the logger
+            logger_name: name of the logger. it should be unique per logger.
         """
         self.logger_name = logger_name
         self.logger: typing.Any = None
 
-    def bind(self, loglevel: str, log_metadata: dict) -> None:
+    def bind(self, level: typing.Union[str, int], log_metadata: dict) -> None:
+        level = self._nameToLevel(level=level)
+
         self._logger = logging.getLogger(self.logger_name)
         handler = logging.StreamHandler()
         formatter = logging.Formatter("%(message)s")
         handler.setFormatter(formatter)
+        handler.setLevel(level)
         if not self._logger.handlers:
             self._logger.addHandler(handler)
-        self._logger.setLevel(loglevel)
+        self._logger.setLevel(level)
         self.logger: logging.LoggerAdapter = NazLoggingAdapter(self._logger, log_metadata)
 
-    def log(self, level: int, log_data: dict) -> None:
+    def log(self, level: typing.Union[str, int], log_data: dict) -> None:
+        level = self._nameToLevel(level=level)
+
         if not self.logger:
-            self.bind(loglevel="DEBUG", log_metadata={})
+            self.bind(level=level, log_metadata={})
         if level >= logging.ERROR:
             self.logger.log(level, log_data, exc_info=True)
         else:
             self.logger.log(level, log_data)
 
+    @staticmethod
+    def _nameToLevel(level: typing.Union[str, int]) -> int:
+        try:
+            if isinstance(level, str):
+                # please mypy
+                _level: int = logging._nameToLevel[level.upper()]
+            else:
+                _level = level
+            return _level
+        except KeyError as e:
+            raise ValueError(
+                "`level` should be one of; 'NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'"
+            ) from e
+
 
 class NazLoggingAdapter(logging.LoggerAdapter):
+    _converter = time.localtime
+    _formatter = logging.Formatter()
+
     def process(self, msg, kwargs):
+        timestamp = self.formatTime()
+
         if isinstance(msg, str):
-            merged_msg = "{0} {1}".format(msg, self.extra)
+            merged_msg = "{0} {1} {2}".format(timestamp, msg, self.extra)
+            if self.extra == {}:
+                merged_msg = "{0} {1}".format(timestamp, msg)
             return merged_msg, kwargs
         else:
-            merged_msg = {**msg, **self.extra}
+            _timestamp = {"timestamp": timestamp}
+            # _timestamp should appear first in resulting dict
+            merged_msg = {**_timestamp, **msg, **self.extra}
             return "{0}".format(merged_msg), kwargs
+
+    def formatTime(self):
+        """
+        Return the creation time of the specified log event as formatted text.
+
+        This code is borrowed from:
+        https://docs.python.org/3/library/logging.html#logging.Formatter.formatTime
+
+        The basic behaviour is as follows: an ISO8601-like (or RFC 3339-like) format is used.
+        This function uses `time.localtime()` to convert the creation time to a tuple.
+        """
+        now = time.time()
+        msecs = (now - int(now)) * 1000
+
+        ct = self._converter(now)
+        t = time.strftime(self._formatter.default_time_format, ct)
+        s = self._formatter.default_msec_format % (t, msecs)
+        return s

naz/ratelimiter.py

@@ -32,30 +32,20 @@ class SimpleRateLimiter(BaseRateLimiter):
 
     .. code-block:: python
 
-        rateLimiter = SimpleRateLimiter(logger=myLogger, send_rate=10, max_tokens=25)
+        rateLimiter = SimpleRateLimiter(logger=myLogger, send_rate=10)
         await rateLimiter.limit()
         send_messsages()
     """
 
-    def __init__(
-        self,
-        logger: logging.LoggerAdapter,
-        send_rate: float = 100_000,
-        max_tokens: float = 100_000,
-        delay_for_tokens: float = 1,
-    ) -> None:
+    def __init__(self, logger: logging.LoggerAdapter, send_rate: float = 100_000) -> None:
         """
         Parameters:
             send_rate: the maximum rate, in messages/second, at which naz can send messages to SMSC.
-            max_tokens: the total number of mesages naz can send before rate limiting kicks in.
-            delay_for_tokens: the duration in seconds which to wait for before checking for token availability after they had finished.
-
-        send_rate and max_tokens should generally be of equal value.
         """
         self.send_rate: float = send_rate
-        self.max_tokens: float = max_tokens
-        self.delay_for_tokens: float = (delay_for_tokens)
+        self.max_tokens: float = self.send_rate
         self.tokens: float = self.max_tokens
+        self.delay_for_tokens: float = 1.0
         self.updated_at: float = time.monotonic()
 
         self.logger = logger

tests/test_client.py

@@ -543,7 +543,7 @@ def mock_create_client():
         )
 
     def test_logger_called(self):
-        with mock.patch("naz.logger.SimpleBaseLogger.log") as mock_logger_log:
+        with mock.patch("naz.logger.SimpleLogger.log") as mock_logger_log:
             mock_logger_log.return_value = None
             self._run(
                 self.cli.parse_response_pdu(