Refactor logs using structlog #168

bigspider · 2020-07-06T13:18:44Z

By using structlog, it's easier to keep the logs structured and decide how to render them for different purposes.

This PR rewrites the logging module to use structlog, keeping them for now as plaintext, with the following settings:

the logs to console is at INFO level
the logs to file is at DEBUG level

Also added a "daemon" parameter, that suppresses output to console. It's not a proper daemon support, as the shell is not released; that's not trivial to do and is left for separate work once we figure out the best way to do it.

This should make it relatively easy to integrate any log aggregator, like the kibana dashboard after #148 is merged.

sr-gi

General comments:

Tests for Logger are missing. I think they can be created now.
Comment for all classes:

I'm thinking this could actually be part of the object __init__ now, and we can avoid hardcoded strings by using name, e.g:

class Inspector:
    def __init__:
        [...]
        self.logger = get_logger(actor=Inspector.__name__)

We may want to change actor, since I don't think no-one ever liked that denomination. What about module or component?

common/logger.py

sr-gi · 2020-07-09T10:45:30Z

common/logger.py

-    Args:
-        log_name_prefix (:obj:`str`): the prefix of the logger where the data will be stored in (server, client, ...).
-        actor (:obj:`str`): the system actor that is logging the event (e.g. ``Watcher``, ``Cryptographer``, ...).
+    Render ``event_dict``. It renders the timestamp, followed by the actor within "[]" (unless it's None),


nit: event_dict (missing `` )

sr-gi · 2020-07-09T10:47:14Z

common/logger.py

-        return msg if self.actor is None else "[{}]: {}".format(self.actor, msg)
+    def _repr(self, val):
+        """
+        Determine representation of *val* depending on its type.


nit: For docstrings, if it is a one-liner, it should be expressed:

""" <docstring> """ (same line, no full stop)

The return is also missing.

Changed to a one-line description, and also made the code more compact with a ternary if/else.

sr-gi · 2020-07-09T10:47:55Z

common/logger.py

-        log_name_prefix (:obj:`str`): the prefix of the logger where the data will be stored in (server, client, ...).
-        actor (:obj:`str`): the system actor that is logging the event (e.g. ``Watcher``, ``Cryptographer``, ...).
+    Render ``event_dict``. It renders the timestamp, followed by the actor within "[]" (unless it's None),
+    followed by the event, then any remaining item in event_dict in the key=value format


docstrings: full-stop.

sr-gi · 2020-07-09T10:48:34Z

common/logger.py

-             msg (:obj:`str`): the message to be logged.
-             kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output.
-        """
+    """


docstring: Unnecessary empty line at the end

Also some nits: space between parameter and type (param (:obj: ...))

No need of parenthesis fort the Return and Raises

sr-gi · 2020-07-09T11:04:49Z

common/logger.py

+        # force event to str for compatibility with standard library
+        event = event_dict.pop("event")
+        if not isinstance(event, str):
+            event = str(event)


I'm guessing you're trying to make sure the event (I'd call it msg or message) is a string here. However you'd have the exact same problem that you solved in key_value_part, if an object with no __str__ method is passed this will fail, so it seems to debunk the purpose of the check.

I'd either use _repr or not have the check + cast at all.

Changed using _repr now.

sr-gi · 2020-07-09T11:22:30Z

common/logger.py

+    global configured
+
+    if configured:
+        raise RuntimeError("logging was already configured.")


Not sure this is really necessary.

The point is that this check is that the function should only be called one, isn't it? But this function is supposed to only be called during bootstrap anyway, isn't it?

In any case, this would raise an exception that no-one captures making either cli or teos to quit execution.

So, either we do not add this, or we implement is as a singleton?

PS: Given that this has no return, but simply configures logging.config.dictConfig, you can simply return None if the condition is met, given that it has been already configured.

Well, I think calling this twice means that your code is broken, so it's good if the exception is not handled. Silently failing (and returning None that will likely be ignored) might lead to not detecting that you called it twice - and maybe running with a config you don't expect.

Well, I don't think the latter would apply, since the the first time it will configure it with the original conf and the second time will not run it at all, so it would still run with the original conf.

I don't think this is a big deal though, since there is no chance this is called more than once.

If you rather leaving it like this: Cap "Logging" and remove the tailing dot

Well, that mean we are choosing the first config, but we don't know which one was the intended one if two are given.

Updated error message in 56adb9b.

sr-gi · 2020-07-09T11:26:02Z

common/logger.py

-    def _create_console_message(self, msg, **kwargs):
-        s_message = _StructuredMessage(self._add_prefix(msg), **kwargs).to_dict()
-        message = "{} {}".format(s_message["time"], s_message["message"])
+    def __call__(self, _, __, event_dict):


docstrings missing.

Added a one-liner docstring, not sure there's more to add as it would repeat the class docstring, basically.

sr-gi · 2020-07-09T11:28:04Z

teos/__init__.py

@@ -17,6 +16,7 @@
    "BTC_FEED_PROTOCOL": {"value": "tcp", "type": str},
    "BTC_FEED_CONNECT": {"value": "localhost", "type": str},
    "BTC_FEED_PORT": {"value": 28332, "type": int},
+    "DAEMON": {"value": 0, "type": int},


Can not this be a boolean?

Actually, read comment in teosd.

Dropped the two commits adding the daemon config.

sr-gi · 2020-07-09T11:56:36Z

teos/teosd.py

@@ -53,7 +53,15 @@ def main(command_line_conf):
            config["BTC_RPC_PORT"] = get_default_rpc_port(config.get("BTC_NETWORK"))

        setup_data_folder(data_dir)
-        setup_logging(config.get("LOG_FILE"), LOG_PREFIX)
+
+        daemon = config.get("DAEMON") != 0


It may be worth separate this to a different PR to avoid mixing stuff

Dropped the two commits adding the daemon config.

…now in common.logger); removed LOG_PREFIX; removed Logger class, replaced with a get_logger method with the 'actor' parameter

…rt of a log entry

bigspider · 2020-07-10T11:11:18Z

Should have addressed almost everything, still a comment suspended about what happens if setup_logging is called twice.

I added tests for the expected output of CustomLogRenderer in various combinations; not sure what tests to add for setup_logging and get_logger. For get_logger, the problem is also that the object returned is kinda opaque: a test that would make sense is to check whether the component is indeed bound to the logger, but didn't find a way without "cheating" by reading private variables in the returned object.

sr-gi

General comments (there's also some inline):

API should have logger as part of the init (using API.name_) instead of globally defined.
Cleaner, Responder, and UserDBM can have the name defined using X.name to get rid of a hardcoded value.
All the clases that now include logger as part of their attributes are missing the corresponding entry in the docstring. Moreover, entries on args and attributes are sorted by appearance.
Needs black formatting (add a file watcher so you can have it applied on every file save).
test_logger has a bunch of unused import (install flake8 and use it to check your files).
test_logger is only covering CustomLogRenderer

sr-gi · 2020-07-10T12:37:15Z

common/logger.py

-    @staticmethod
-    def _create_file_message(msg, **kwargs):
-        return json.dumps(_StructuredMessage(msg, **kwargs).to_dict())
+        # Represent all the key=value elements still in event_dict


We can surround this by parenthesis so it is easier to parse in case we ever need to:

ts [component] msg (key1=value1, ...)

Good idea, done in e260149.

bigspider · 2020-07-13T08:44:26Z

Should have addressed all the comments. Added the logger to the docstrings (without specifying the type, though). Added a test for get_logger which is a bit unusual, but the only way I found to test it using only the public interface of the object returned by get_logger. There are still no tests for setup_logger, but I don't thing there's much to test there, tbh.

bigspider force-pushed the 165-logs branch from 2416861 to d912451 Compare July 6, 2020 15:09

bigspider marked this pull request as ready for review July 7, 2020 12:52

bigspider requested a review from sr-gi July 7, 2020 13:07

This was referenced Jul 7, 2020

Rework logs #165

Closed

Have a proper 'daemon' mode for teosd #172

Closed

sr-gi suggested changes Jul 9, 2020

View reviewed changes

bigspider force-pushed the 165-logs branch 2 times, most recently from 9392c65 to da4439b Compare July 10, 2020 10:05

bigspider added 7 commits July 10, 2020 12:10

Added structlog and config; removed setup_logging from common.tools (…

a595055

…now in common.logger); removed LOG_PREFIX; removed Logger class, replaced with a get_logger method with the 'actor' parameter

Better docs

46418ea

Added custom Renderer for logs; removed unused log processors

6b8af2e

Removed wrong import

ce109d1

Removed wrong unused processors; added separator for the key-value pa…

94e1959

…rt of a log entry

Fix typos

4eb7f76

Added structlog as requirements for teos_cli

ebb157a

bigspider force-pushed the 165-logs branch 2 times, most recently from f3253f5 to b29eb0d Compare July 10, 2020 10:52

bigspider added 3 commits July 10, 2020 12:54

Addressing some comments from the PR; changed "actor" to "component"

59ec971

Moved logger to class member wherever possible

e30b92f

Fixed missing import after rebase

ae108a1

bigspider force-pushed the 165-logs branch from b29eb0d to ae108a1 Compare July 10, 2020 10:54

bigspider requested a review from sr-gi July 10, 2020 11:11

Added tests for CustomLogRenderer

57ff453

bigspider force-pushed the 165-logs branch from b1d7c66 to 57ff453 Compare July 10, 2020 11:12

Update error message as per PR review

56adb9b

sr-gi suggested changes Jul 10, 2020

View reviewed changes

bigspider added 3 commits July 13, 2020 09:09

Improvements from PR review

d2d2d32

Fix typo in Gatekeeper's docstring

4bc8a31

Add commas and parentheses to extra arguments in console logs

e260149

bigspider force-pushed the 165-logs branch from aa8ace8 to e260149 Compare July 13, 2020 08:11

bigspider added 2 commits July 13, 2020 10:13

Fix typo in docs

72f4d4b

Added test for get_logger

28033cd

bigspider requested a review from sr-gi July 13, 2020 08:44

sr-gi and others added 5 commits July 13, 2020 11:20

common - fix formatting issues

6d93a57

test - fix formatting issues

728ae3d

Filter out logs that are not from teos

d54397e

teos - removes unnecesary log setup in API after d54397e

e2bbf0e

common + test - changes tab for two spaces for logger key_value_part

0cf7ce1

sr-gi force-pushed the 165-logs branch from e777139 to 0cf7ce1 Compare July 13, 2020 10:54

sr-gi approved these changes Jul 13, 2020

View reviewed changes

bigspider merged commit 9b8c5a2 into talaia-labs:master Jul 13, 2020

bigspider deleted the 165-logs branch July 13, 2020 11:08

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refactor logs using structlog #168

Refactor logs using structlog #168

bigspider commented Jul 6, 2020 •

edited

Loading

sr-gi left a comment

sr-gi Jul 9, 2020

bigspider Jul 10, 2020

sr-gi Jul 9, 2020

bigspider Jul 10, 2020

sr-gi Jul 9, 2020

bigspider Jul 10, 2020

sr-gi Jul 9, 2020

sr-gi Jul 9, 2020 •

edited

Loading

bigspider Jul 10, 2020

sr-gi Jul 9, 2020

bigspider Jul 10, 2020

sr-gi Jul 9, 2020

bigspider Jul 10, 2020

sr-gi Jul 10, 2020

bigspider Jul 10, 2020

sr-gi Jul 9, 2020

bigspider Jul 10, 2020

sr-gi Jul 9, 2020

sr-gi Jul 9, 2020

bigspider Jul 10, 2020

sr-gi Jul 9, 2020

bigspider Jul 10, 2020

bigspider commented Jul 10, 2020

sr-gi left a comment •

edited

Loading

sr-gi Jul 10, 2020

bigspider Jul 13, 2020

bigspider commented Jul 13, 2020

Refactor logs using structlog #168

Refactor logs using structlog #168

Conversation

bigspider commented Jul 6, 2020 • edited Loading

sr-gi 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

sr-gi Jul 9, 2020 • edited Loading

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

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

bigspider commented Jul 10, 2020

sr-gi left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bigspider commented Jul 13, 2020

bigspider commented Jul 6, 2020 •

edited

Loading

sr-gi Jul 9, 2020 •

edited

Loading

sr-gi left a comment •

edited

Loading