From 46ee44a2e449538f86e45d71d9bbd38a31aafe2d Mon Sep 17 00:00:00 2001 From: komuW Date: Sun, 26 May 2019 16:34:51 +0300 Subject: [PATCH 1/9] f --- cli/cli.py | 2 +- documentation/config.md | 2 +- documentation/sphinx-docs/logger.rst | 2 +- naz/client.py | 2 +- naz/logger.py | 76 ++++++++++++++++++++++------ tests/test_client.py | 2 +- tests/test_logger.py | 2 +- 7 files changed, 67 insertions(+), 21 deletions(-) diff --git a/cli/cli.py b/cli/cli.py index a32bd72a..69ff9d95 100644 --- a/cli/cli.py +++ b/cli/cli.py @@ -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() diff --git a/documentation/config.md b/documentation/config.md index e21865e1..1e8cf573 100644 --- a/documentation/config.md +++ b/documentation/config.md @@ -48,7 +48,7 @@ encoding | encoding1 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 diff --git a/documentation/sphinx-docs/logger.rst b/documentation/sphinx-docs/logger.rst index 7d01f631..5544d0b5 100644 --- a/documentation/sphinx-docs/logger.rst +++ b/documentation/sphinx-docs/logger.rst @@ -2,6 +2,6 @@ logger --------------- .. automodule:: naz.logger - :members: BaseLogger, SimpleBaseLogger + :members: BaseLogger, SimpleLogger :show-inheritance: diff --git a/naz/client.py b/naz/client.py index 10327b60..915e9466 100644 --- a/naz/client.py +++ b/naz/client.py @@ -216,7 +216,7 @@ def __init__( # 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 = logger.SimpleLogger("naz.client") self.logger.bind(loglevel=self.loglevel, log_metadata=self.log_metadata) self._sanity_check_logger() diff --git a/naz/logger.py b/naz/logger.py index 8e8c757c..9b96e4dc 100644 --- a/naz/logger.py +++ b/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,10 +25,10 @@ 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. @@ -35,20 +36,20 @@ def log(self, level: int, log_data: dict) -> None: 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,80 @@ 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) + def _nameToLevel(self, 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 diff --git a/tests/test_client.py b/tests/test_client.py index 974af30c..a15d74dc 100644 --- a/tests/test_client.py +++ b/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( diff --git a/tests/test_logger.py b/tests/test_logger.py index 1d36e8f3..2a043570 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -18,7 +18,7 @@ class TestLogger(TestCase): """ def setUp(self): - self.logger = naz.logger.SimpleBaseLogger("myLogger") + self.logger = naz.logger.SimpleLogger("myLogger") def tearDown(self): pass From b4656e0ee322436b0fe44eebf334b8f58829b95c Mon Sep 17 00:00:00 2001 From: komuW Date: Sun, 26 May 2019 16:36:18 +0300 Subject: [PATCH 2/9] f --- cli/cli.py | 2 +- naz/client.py | 2 +- tests/test_logger.py | 10 +++++----- 3 files changed, 7 insertions(+), 7 deletions(-) diff --git a/cli/cli.py b/cli/cli.py index 69ff9d95..8622d650 100644 --- a/cli/cli.py +++ b/cli/cli.py @@ -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: diff --git a/naz/client.py b/naz/client.py index 915e9466..24af4a09 100644 --- a/naz/client.py +++ b/naz/client.py @@ -217,7 +217,7 @@ def __init__( self.logger = log_handler if not self.logger: self.logger = logger.SimpleLogger("naz.client") - self.logger.bind(loglevel=self.loglevel, log_metadata=self.log_metadata) + self.logger.bind(level=self.loglevel, log_metadata=self.log_metadata) self._sanity_check_logger() self.rateLimiter = rateLimiter diff --git a/tests/test_logger.py b/tests/test_logger.py index 2a043570..c4da23d3 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -24,7 +24,7 @@ def tearDown(self): pass def test_can_bind(self): - self.logger.bind(loglevel="INFO", log_metadata={"customer_id": "34541"}) + self.logger.bind(level="INFO", log_metadata={"customer_id": "34541"}) def test_can_log_string(self): self.logger.log(level=logging.WARN, log_data="can log string") @@ -38,11 +38,11 @@ def test_can_log_dict(self): ) def test_bind_and_log_string(self): - self.logger.bind(loglevel="INFO", log_metadata={"customer_id": "34541"}) + self.logger.bind(level="INFO", log_metadata={"customer_id": "34541"}) self.logger.log(level=logging.WARN, log_data="can log string") def test_bind_and_log_dict(self): - self.logger.bind(loglevel="INFO", log_metadata={"customer_id": "34541"}) + self.logger.bind(level="INFO", log_metadata={"customer_id": "34541"}) self.logger.log(level=logging.WARN, log_data={"name": "Magic Johnson"}) @@ -61,7 +61,7 @@ def __init__(self): self.logger.addHandler(handler) self.logger.setLevel("DEBUG") - def bind(self, loglevel, log_metadata): + def bind(self, level, log_metadata): pass def log(self, level, log_data): @@ -85,7 +85,7 @@ def tearDown(self): pass def test_can_bind(self): - self.kvLog.bind(loglevel="INFO", log_metadata={"customer_id": "34541"}) + self.kvLog.bind(level="INFO", log_metadata={"customer_id": "34541"}) def test_can_log_dict(self): log_id = 234_255 From 9be10828ba70d60438eeb40d3042cedad1c39270 Mon Sep 17 00:00:00 2001 From: komuW Date: Sun, 26 May 2019 16:38:00 +0300 Subject: [PATCH 3/9] f --- README.md | 2 +- cli/cli.py | 2 +- naz/client.py | 4 ++-- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index 22596fad..135c58ce 100644 --- a/README.md +++ b/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 ``` diff --git a/cli/cli.py b/cli/cli.py index 8622d650..89658475 100644 --- a/cli/cli.py +++ b/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", ) diff --git a/naz/client.py b/naz/client.py index 24af4a09..c8c2ceb1 100644 --- a/naz/client.py +++ b/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 ) ) From 1a23c302e9151b8fc6b8458d2afe44f53ec194a4 Mon Sep 17 00:00:00 2001 From: komuW Date: Sun, 26 May 2019 16:44:06 +0300 Subject: [PATCH 4/9] f --- naz/logger.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/naz/logger.py b/naz/logger.py index 9b96e4dc..567d1a4a 100644 --- a/naz/logger.py +++ b/naz/logger.py @@ -86,7 +86,8 @@ def log(self, level: typing.Union[str, int], log_data: dict) -> None: else: self.logger.log(level, log_data) - def _nameToLevel(self, level: typing.Union[str, int]) -> int: + @staticmethod + def _nameToLevel(level: typing.Union[str, int]) -> int: try: if isinstance(level, str): # please mypy From 71658ead3a86162d12a4f0184b4bf42802178b87 Mon Sep 17 00:00:00 2001 From: komuW Date: Sun, 26 May 2019 17:00:15 +0300 Subject: [PATCH 5/9] f --- naz/client.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/naz/client.py b/naz/client.py index c8c2ceb1..e117cb6a 100644 --- a/naz/client.py +++ b/naz/client.py @@ -427,7 +427,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 +490,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 +512,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 +552,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 +776,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 +872,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", From 7c08721b958526a790b3f735e0ac7f1338684d91 Mon Sep 17 00:00:00 2001 From: komuW Date: Sun, 26 May 2019 17:02:00 +0300 Subject: [PATCH 6/9] f --- CHANGELOG.md | 3 +++ naz/__version__.py | 2 +- 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 215b8c3a..60ef1f11 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/naz/__version__.py b/naz/__version__.py index 321ad0ae..421f176d 100644 --- a/naz/__version__.py +++ b/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", From 4cd9552a4b005d8efcf0849c6276282b4743bc87 Mon Sep 17 00:00:00 2001 From: komuW Date: Sun, 26 May 2019 17:05:29 +0300 Subject: [PATCH 7/9] f --- naz/hooks.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/naz/hooks.py b/naz/hooks.py index 0eea1cdb..10abb603 100644 --- a/naz/hooks.py +++ b/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", From 999950536eafeac2bb1a38b2c26ac8072d69f58e Mon Sep 17 00:00:00 2001 From: komuW Date: Sun, 26 May 2019 17:14:05 +0300 Subject: [PATCH 8/9] f --- naz/ratelimiter.py | 18 ++++-------------- tests/test_ratelimit.py | 17 +++++------------ 2 files changed, 9 insertions(+), 26 deletions(-) diff --git a/naz/ratelimiter.py b/naz/ratelimiter.py index db652c19..d3196cbc 100644 --- a/naz/ratelimiter.py +++ b/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 diff --git a/tests/test_ratelimit.py b/tests/test_ratelimit.py index bc1b310f..4bd7db40 100644 --- a/tests/test_ratelimit.py +++ b/tests/test_ratelimit.py @@ -42,13 +42,8 @@ def setUp(self): self.logger.setLevel("DEBUG") self.send_rate = 1 - self.max_tokens = 1 - self.delay_for_tokens = 1 self.rateLimiter = naz.ratelimiter.SimpleRateLimiter( - logger=self.logger, - send_rate=self.send_rate, - max_tokens=self.max_tokens, - delay_for_tokens=self.delay_for_tokens, + logger=self.logger, send_rate=self.send_rate ) def tearDown(self): @@ -61,22 +56,20 @@ def _run(coro): def test_no_rlimit(self): with mock.patch("naz.ratelimiter.asyncio.sleep", new=AsyncMock()) as mock_sleep: - for _ in range(0, self.max_tokens): + for _ in range(0, self.send_rate): self._run(self.rateLimiter.limit()) self.assertFalse(mock_sleep.mock.called) def test_token_exhaustion_causes_rlimit(self): with mock.patch("naz.ratelimiter.asyncio.sleep", new=AsyncMock()) as mock_sleep: - for _ in range(0, self.max_tokens * 2): + for _ in range(0, self.send_rate * 2): self._run(self.rateLimiter.limit()) self.assertTrue(mock_sleep.mock.called) - self.assertEqual(mock_sleep.mock.call_args[0][0], self.delay_for_tokens) + self.assertEqual(mock_sleep.mock.call_args[0][0], self.rateLimiter.delay_for_tokens) def test_send_rate(self): send_rate = 3 - rLimiter = naz.ratelimiter.SimpleRateLimiter( - logger=self.logger, send_rate=send_rate, max_tokens=3, delay_for_tokens=1 - ) + rLimiter = naz.ratelimiter.SimpleRateLimiter(logger=self.logger, send_rate=send_rate) msgs_delivered = [] now = time.monotonic() for _ in range(0, send_rate * 4): From 2802033dcd34535fe14f8ecd1e63c14c6799da2b Mon Sep 17 00:00:00 2001 From: komuW Date: Sun, 26 May 2019 17:17:23 +0300 Subject: [PATCH 9/9] f --- naz/client.py | 1 - 1 file changed, 1 deletion(-) diff --git a/naz/client.py b/naz/client.py index e117cb6a..08969684 100644 --- a/naz/client.py +++ b/naz/client.py @@ -213,7 +213,6 @@ 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.SimpleLogger("naz.client")