Add more configurable JSON logging (#246)

* add JSON formatter by @zblevins

* add json logging to config generator, clean up init

* change run instructions to use pip install

* flake8 fixes

* clean up

* more cleanup and simplification

* add a couple of tests, update requirements, fix warnings

* the time is gone, the song is over

* cleanup, flake8

* one more flake8 fix

* formatting fixes from black

* add caller information in log emissions

README.md

@@ -19,7 +19,7 @@ an AWS account.
 mkvirtualenv repokid
 git clone git@github.com:Netflix/repokid.git
 cd repokid
-python setup.py develop
+pip install -e .
 repokid config config.json
 ```
 

repokid/__init__.py

@@ -12,29 +12,15 @@
 #     See the License for the specific language governing permissions and
 #     limitations under the License.
 import collections
-import datetime
 import inspect
 import json
+import logging
 import logging.config
 import os
-import socket
-import sys
 
 import import_string
-import logmatic
-from pytz import timezone
 
-__version__ = "0.11.0"
-
-
-class ContextFilter(logging.Filter):
-    """Logging Filter for adding hostname to log entries."""
-
-    hostname = socket.gethostname()
-
-    def filter(self, record):
-        record.hostname = ContextFilter.hostname
-        return True
+__version__ = "0.11.1"
 
 
 def init_config():
@@ -83,28 +69,14 @@ def init_logging():
     suppressed_loggers = [
         "botocore.vendored.requests.packages.urllib3.connectionpool",
         "urllib3",
+        "botocore.credentials",
     ]
 
     for logger in suppressed_loggers:
         logging.getLogger(logger).setLevel(logging.ERROR)
 
     log = logging.getLogger(__name__)
-    log.addFilter(ContextFilter())
-    extra = {"eventTime": datetime.datetime.now(timezone("US/Pacific")).isoformat()}
     log.propagate = False
-    handler = logging.StreamHandler(sys.stdout)
-    handler.setLevel("DEBUG")
-    log.addHandler(handler)
-    if CONFIG:
-        json_logging_file = CONFIG.get("json_logging_file")
-        if json_logging_file:
-            if "~" in json_logging_file:
-                json_logging_file = os.path.expanduser(json_logging_file)
-            os.makedirs(os.path.dirname(json_logging_file), exist_ok=True)
-            file_handler = logging.FileHandler(json_logging_file)
-            file_handler.setFormatter(logmatic.JsonFormatter())
-            log.addHandler(file_handler)
-    log = logging.LoggerAdapter(log, extra)
     return log
 
 

repokid/cli/repokid_cli.py

@@ -136,7 +136,8 @@ def _generate_default_config(filename=None):
             "formatters": {
                 "standard": {
                     "format": "%(asctime)s %(levelname)s: %(message)s [in %(pathname)s:%(lineno)d]"
-                }
+                },
+                "json": {"class": "repokid.utils.logging.JSONFormatter"},
             },
             "handlers": {
                 "file": {
@@ -148,14 +149,28 @@ def _generate_default_config(filename=None):
                     "backupCount": 100,
                     "encoding": "utf8",
                 },
+                "json_file": {
+                    "class": "logging.handlers.RotatingFileHandler",
+                    "level": "INFO",
+                    "formatter": "json",
+                    "filename": "repokid.json",
+                    "maxBytes": 10485760,
+                    "backupCount": 100,
+                    "encoding": "utf8",
+                },
                 "console": {
                     "class": "logging.StreamHandler",
                     "level": "INFO",
                     "formatter": "standard",
                     "stream": "ext://sys.stdout",
                 },
             },
-            "loggers": {"repokid": {"handlers": ["file", "console"], "level": "INFO"}},
+            "loggers": {
+                "repokid": {
+                    "handlers": ["file", "json_file", "console"],
+                    "level": "INFO",
+                }
+            },
         },
         "opt_out_period_days": 90,
         "dispatcher": {
@@ -983,7 +998,7 @@ def _replace_policies(repoed_policies, role, account_number, conn):
                 RoleName=role.role_name,
                 PolicyName=policy_name,
                 PolicyDocument=json.dumps(policy, indent=2, sort_keys=True),
-                **conn
+                **conn,
             )
 
         except botocore.exceptions.ClientError as e:
@@ -1380,7 +1395,7 @@ def rollback_role(
                 RoleName=role.role_name,
                 PolicyName=policy_name,
                 PolicyDocument=json.dumps(policy, indent=2, sort_keys=True),
-                **conn
+                **conn,
             )
 
         except botocore.exceptions.ClientError as e:

repokid/tests/test_logging.py

@@ -0,0 +1,42 @@
+from mock import patch
+from repokid.utils.logging import JSONFormatter
+
+
+class MockRecord(object):
+    def __init__(self, message):
+        self.created = 1579129029
+        self.levelname = "INFO"
+        self.name = "repokid_test"
+        self.message = message
+        self.process = 12345
+        self.threadName = "MainThread"
+        self.exc_info = None
+        self.filename = "hack_the_planet.py"
+        self.funcName = "exploit"
+        self.lineno = 42
+
+    def getMessage(self):
+        return self.message
+
+
+class TestLogging(object):
+    formatter = JSONFormatter()
+    formatter.hostname = "test_host"
+
+    def test_format(self):
+        record = MockRecord("Hi there!")
+        result = self.formatter.format(record)
+        expected = """{"time": "2020-01-15T22:57:09", "level": "INFO", "name": "repokid_test", "message": "Hi there!", "process": 12345, "thread": "MainThread", "hostname": "test_host", "filename": "hack_the_planet.py", "function": "exploit", "lineNo": 42}"""  # noqa: E501
+        assert result == expected
+
+    def test_format_with_exception(self):
+        record = MockRecord("Hi there!")
+        record.exc_info = (
+            AttributeError,
+            AttributeError("you did a wrong thing"),
+            None,
+        )
+        with patch("traceback.format_exc", return_value="this is totally a traceback"):
+            result = self.formatter.format(record)
+        expected = """{"time": "2020-01-15T22:57:09", "level": "INFO", "name": "repokid_test", "message": "Hi there!", "process": 12345, "thread": "MainThread", "hostname": "test_host", "filename": "hack_the_planet.py", "function": "exploit", "lineNo": 42, "exception": "AttributeError: you did a wrong thing", "traceback": "this is totally a traceback"}"""  # noqa: E501
+        assert result == expected

repokid/utils/logging.py

@@ -0,0 +1,34 @@
+from datetime import datetime
+import json
+import logging
+from socket import gethostname
+import traceback
+
+
+class JSONFormatter(logging.Formatter):
+    """Custom formatter to output log records as JSON."""
+
+    hostname = gethostname()
+
+    def format(self, record):
+        """Format the given record into JSON."""
+        message = {
+            "time": datetime.utcfromtimestamp(record.created).isoformat(),
+            "level": record.levelname,
+            "name": record.name,
+            "message": record.getMessage(),
+            "process": record.process,
+            "thread": record.threadName,
+            "hostname": self.hostname,
+            "filename": record.filename,
+            "function": record.funcName,
+            "lineNo": record.lineno,
+        }
+
+        if record.exc_info:
+            message[
+                "exception"
+            ] = f"{record.exc_info[0].__name__}: {record.exc_info[1]}"
+            message["traceback"] = traceback.format_exc()
+
+        return json.dumps(message, ensure_ascii=False)

repokid/utils/roledata.py

@@ -525,13 +525,13 @@ def _get_potentially_repoable_permissions(
         potentially_repoable_permissions.items()
     ):
         if permission_name.split(":")[0] in IAM_ACCESS_ADVISOR_UNSUPPORTED_SERVICES:
-            LOGGER.warn("skipping {}".format(permission_name))
+            LOGGER.warning("skipping {}".format(permission_name))
             continue
 
         # we have an unused service but need to make sure it's repoable
         if permission_name.split(":")[0] not in used_services:
             if permission_name in IAM_ACCESS_ADVISOR_UNSUPPORTED_ACTIONS:
-                LOGGER.warn("skipping {}".format(permission_name))
+                LOGGER.warning("skipping {}".format(permission_name))
                 continue
 
             permission_decision.repoable = True

requirements.in

@@ -2,7 +2,6 @@ boto3
 cloudaux
 docopt
 import_string
-logmatic-python
 marshmallow<3
 policyuniverse
 requests

requirements.txt

@@ -2,7 +2,7 @@
 # This file is autogenerated by pip-compile
 # To update, run:
 #
-#    pip-compile --output-file requirements.txt requirements.in
+#    pip-compile requirements.in
 #
 
 bleach==3.1.0             # via readme-renderer
@@ -22,14 +22,12 @@ import-string==0.1.0
 inflection==0.3.1         # via cloudaux
 jmespath==0.9.4           # via boto3, botocore
 joblib==0.13.2            # via cloudaux
-logmatic-python==0.1.7
 marshmallow==2.20.2
-pip-tools==4.1.0
+pip-tools==4.3.0
 pkginfo==1.5.0.1          # via twine
 policyuniverse==1.3.2.0
 pygments==2.4.2           # via readme-renderer
 python-dateutil==2.8.0    # via botocore
-python-json-logger==0.1.11  # via logmatic-python
 pytz==2019.2
 raven==6.10.0
 readme-renderer==24.0     # via twine