Add preliminary support for logging

Current logging mechanism makes use of Python's logging module.
MySQL logging handler inserts log entries to MySQL server and
another logging handler is used to stream events to web interface
via nginx streaming push.

README.rst

@@ -67,7 +67,8 @@ To install Certidude:
 
 .. code:: bash
 
-    apt-get install -y python3 python3-pip python3-dev python3-mysql.connector cython3 build-essential libffi-dev libssl-dev libkrb5-dev
+    apt-get install -y python3 python3-pip python3-dev cython3 build-essential libffi-dev libssl-dev libkrb5-dev
+    pip3 install --allow-external mysql-connector-python  mysql-connector-python
     pip3 install certidude
 
 Make sure you're running PyOpenSSL 0.15+ and netifaces 0.10.4+ from PyPI,

certidude/api/__init__.py

@@ -35,7 +35,7 @@ class SessionResource(object):
     @event_source
     def on_get(self, req, resp):
         return dict(
-            username=req.context.get("user")[0],
+            username=req.context.get("user"),
             event_channel = config.PUSH_EVENT_SOURCE % config.PUSH_TOKEN,
             autosign_subnets = config.AUTOSIGN_SUBNETS,
             request_subnets = config.REQUEST_SUBNETS,
@@ -78,6 +78,7 @@ def certidude_app():
     from .request import RequestListResource, RequestDetailResource
     from .lease import LeaseResource
     from .whois import WhoisResource
+    from .log import LogResource
 
     app = falcon.API()
 
@@ -89,10 +90,51 @@ def certidude_app():
     app.add_route("/api/signed/", SignedCertificateListResource())
     app.add_route("/api/request/{cn}/", RequestDetailResource())
     app.add_route("/api/request/", RequestListResource())
+    app.add_route("/api/log/", LogResource())
     app.add_route("/api/", SessionResource())
 
     # Gateway API calls, should this be moved to separate project?
     app.add_route("/api/lease/", LeaseResource())
     app.add_route("/api/whois/", WhoisResource())
 
+    """
+    Set up logging
+    """
+
+    from certidude import config
+    from certidude.mysqllog import MySQLLogHandler
+    from datetime import datetime
+    import logging
+    import socket
+    import json
+
+
+    class PushLogHandler(logging.Handler):
+        def emit(self, record):
+            from certidude.push import publish
+            print("EVENT HAPPENED:", record.created)
+            publish("log-entry", dict(
+                created = datetime.fromtimestamp(record.created),
+                message = record.msg % record.args,
+                severity = record.levelname.lower()))
+
+    sql_handler = MySQLLogHandler(config.DATABASE_POOL)
+    push_handler = PushLogHandler()
+
+    for facility in "api", "cli":
+        logger = logging.getLogger(facility)
+        logger.setLevel(logging.DEBUG)
+        logger.addHandler(sql_handler)
+        logger.addHandler(push_handler)
+
+
+    logging.getLogger("cli").info("Started Certidude at %s", socket.getaddrinfo(socket.gethostname(), 0, flags=socket.AI_CANONNAME)[0][3])
+
+    import atexit
+
+    def exit_handler():
+        logging.getLogger("cli").info("Shutting down Certidude")
+
+    atexit.register(exit_handler)
+
     return app

certidude/api/log.py

@@ -0,0 +1,39 @@
+
+from certidude import config
+from certidude.auth import login_required, authorize_admin
+from certidude.decorators import serialize
+
+class LogResource(object):
+    @serialize
+    @login_required
+    @authorize_admin
+    def on_get(self, req, resp):
+        """
+        Translate currently online client's IP-address to distinguished name
+        """
+
+        SQL_LOG_ENTRIES = """
+            SELECT
+                *
+            FROM
+                log
+            ORDER BY created DESC
+        """
+        conn = config.DATABASE_POOL.get_connection()
+        cursor = conn.cursor(dictionary=True)
+        cursor.execute(SQL_LOG_ENTRIES)
+
+        def g():
+            for row in cursor:
+                yield row
+            cursor.close()
+            conn.close()
+        return tuple(g())
+
+#        for acquired, released, identity in cursor:
+#            return {
+#                "acquired": datetime.utcfromtimestamp(acquired),
+#                "identity": parse_dn(bytes(identity))
+#            }
+#        return None
+        

certidude/api/request.py

@@ -1,6 +1,7 @@
 
 import click
 import falcon
+import logging
 import ipaddress
 import os
 from certidude import config, authority, helpers, push
@@ -8,6 +9,8 @@ from certidude.auth import login_required, authorize_admin
 from certidude.decorators import serialize
 from certidude.wrappers import Request, Certificate
 
+logger = logging.getLogger("api")
+
 class RequestListResource(object):
     @serialize
     @authorize_admin
@@ -27,13 +30,14 @@ class RequestListResource(object):
                 if subnet.overlaps(remote_addr):
                     break
             else:
+               logger.warning("Attempted to submit signing request from non-whitelisted address %s", req.env["REMOTE_ADDR"])
                raise falcon.HTTPForbidden("Forbidden", "IP address %s not whitelisted" % remote_addr)
 
         if req.get_header("Content-Type") != "application/pkcs10":
             raise falcon.HTTPUnsupportedMediaType(
                 "This API call accepts only application/pkcs10 content type")
 
-        body = req.stream.read(req.content_length)
+        body = req.stream.read(req.content_length).decode("ascii")
         csr = Request(body)
 
         # Check if this request has been already signed and return corresponding certificte if it has been signed
@@ -65,6 +69,7 @@ class RequestListResource(object):
         try:
             csr = authority.store_request(body)
         except FileExistsError:
+            logger.warning("Rejected signing request with overlapping common name from %s", req.env["REMOTE_ADDR"])
             raise falcon.HTTPConflict(
                 "CSR with such CN already exists",
                 "Will not overwrite existing certificate signing request, explicitly delete CSR and try again")
@@ -77,9 +82,11 @@ class RequestListResource(object):
             click.echo("Redirecting to: %s"  % url)
             resp.status = falcon.HTTP_SEE_OTHER
             resp.set_header("Location", url)
+            logger.warning("Redirecting signing request from %s to %s", req.env["REMOTE_ADDR"], url)
         else:
             # Request was accepted, but not processed
             resp.status = falcon.HTTP_202
+            logger.info("Signing request from %s stored", req.env["REMOTE_ADDR"])
 
 
 class RequestDetailResource(object):
@@ -108,6 +115,7 @@ class RequestDetailResource(object):
         resp.body = "Certificate successfully signed"
         resp.status = falcon.HTTP_201
         resp.location = os.path.join(req.relative_uri, "..", "..", "signed", cn)
+        logger.info("Signing request %s signed by %s from %s", csr.common_name, req.context["user"], req.env["REMOTE_ADDR"])
 
     @login_required
     @authorize_admin
@@ -116,4 +124,5 @@ class RequestDetailResource(object):
             authority.delete_request(cn)
         except FileNotFoundError:
             resp.body = "No certificate CN=%s found" % cn
+            logger.warning("User %s attempted to delete non-existant signing request %s from %s", req.context["user"], cn, req.env["REMOTE_ADDR"])
             raise falcon.HTTPNotFound()

certidude/auth.py

@@ -3,10 +3,13 @@ import click
 import falcon
 import ipaddress
 import kerberos
+import logging
 import os
 import re
 import socket
 
+logger = logging.getLogger("api")
+
 # Vanilla Kerberos provides only username.
 # AD also embeds PAC (Privilege Attribute Certificate), which
 # is supposed to be sent via HTTP headers and it contains
@@ -30,11 +33,12 @@ else:
     click.echo("Kerberos enabled, service principal is HTTP/%s" % FQDN)
 
 def login_required(func):
-    def wrapped(resource, req, resp, *args, **kwargs):
+    def authenticate(resource, req, resp, *args, **kwargs):
         authorization = req.get_header("Authorization")
 
         if not authorization:
             resp.append_header("WWW-Authenticate", "Negotiate")
+            logger.debug("No Kerberos ticket offered while attempting to access %s from %s", req.env["PATH_INFO"], req.env["REMOTE_ADDR"])
             raise falcon.HTTPUnauthorized("Unauthorized", "No Kerberos ticket offered, are you sure you've logged in with domain user account?")
 
         token = ''.join(authorization.split()[1:])
@@ -42,6 +46,7 @@ def login_required(func):
         try:
             result, context = kerberos.authGSSServerInit("HTTP@" + FQDN)
         except kerberos.GSSError as ex:
+            # TODO: logger.error
             raise falcon.HTTPForbidden("Forbidden", "Authentication System Failure: %s(%s)" % (ex.args[0][0], ex.args[1][0],))
 
         try:
@@ -49,28 +54,35 @@ def login_required(func):
         except kerberos.GSSError as ex:
             s = str(dir(ex))
             kerberos.authGSSServerClean(context)
+            # TODO: logger.error
             raise falcon.HTTPForbidden("Forbidden", "Bad credentials: %s (%s)" % (ex.args[0][0], ex.args[1][0]))
         except kerberos.KrbError as ex:
             kerberos.authGSSServerClean(context)
+            # TODO: logger.error
             raise falcon.HTTPForbidden("Forbidden", "Bad credentials: %s" % (ex.args[0],))
 
-        req.context["user"] = kerberos.authGSSServerUserName(context).split("@")
+        user = kerberos.authGSSServerUserName(context)
+        req.context["user"], req.context["user_realm"] = user.split("@")
 
         try:
             # BUGBUG: https://github.com/02strich/pykerberos/issues/6
             #kerberos.authGSSServerClean(context)
             pass
         except kerberos.GSSError as ex:
+            # TODO: logger.error
             raise error.LoginFailed('Authentication System Failure %s(%s)' % (ex.args[0][0], ex.args[1][0],))
 
         if result == kerberos.AUTH_GSS_COMPLETE:
+            logger.debug("Succesfully authenticated user %s for %s from %s", user, req.env["PATH_INFO"], req.env["REMOTE_ADDR"])
             return func(resource, req, resp, *args, **kwargs)
         elif result == kerberos.AUTH_GSS_CONTINUE:
+            # TODO: logger.error
             raise falcon.HTTPUnauthorized("Unauthorized", "Tried GSSAPI")
         else:
+            # TODO: logger.error
             raise falcon.HTTPForbidden("Forbidden", "Tried GSSAPI")
 
-    return wrapped
+    return authenticate
 
 
 def authorize_admin(func):
@@ -85,12 +97,13 @@ def authorize_admin(func):
             if subnet.overlaps(remote_addr):
                 break
         else:
+            logger.info("Rejected access to administrative call %s by %s from %s, source address not whitelisted", req.env["PATH_INFO"], user, req.env["REMOTE_ADDR"])
             raise falcon.HTTPForbidden("Forbidden", "Remote address %s not whitelisted" % remote_addr)
 
         # Check for username whitelist
-        kerberos_username, kerberos_realm = req.context.get("user")
+        if req.context.get("user") not in config.ADMIN_USERS:
-        if kerberos_username not in config.ADMIN_USERS:
+            logger.info("Rejected access to administrative call %s by %s from %s, user not whitelisted", req.env["PATH_INFO"], user, req.env["REMOTE_ADDR"])
-            raise falcon.HTTPForbidden("Forbidden", "User %s not whitelisted" % kerberos_username)
+            raise falcon.HTTPForbidden("Forbidden", "User %s not whitelisted" % req.context.get("user"))
 
         # Retain username, TODO: Better abstraction with username, e-mail, sn, gn?
 

certidude/authority.py

@@ -66,7 +66,7 @@ def store_request(buf, overwrite=False):
             raise FileExistsError("Request already exists")
     else:
         with open(request_path + ".part", "wb") as fh:
-            fh.write(buf)
+            fh.write(buf.encode("ascii"))
         os.rename(request_path + ".part", request_path)
 
     return Request(open(request_path))

certidude/config.py

@@ -3,6 +3,7 @@ import click
 import configparser
 import ipaddress
 import os
+import socket
 import string
 from random import choice
 
@@ -24,6 +25,8 @@ REQUESTS_DIR = cp.get("authority", "requests_dir")
 SIGNED_DIR = cp.get("authority", "signed_dir")
 REVOKED_DIR = cp.get("authority", "revoked_dir")
 
+#LOG_DATA = cp.get("logging", "database")
+
 CERTIFICATE_BASIC_CONSTRAINTS = "CA:FALSE"
 CERTIFICATE_KEY_USAGE_FLAGS = "nonRepudiation,digitalSignature,keyEncipherment"
 CERTIFICATE_EXTENDED_KEY_USAGE_FLAGS = "clientAuth"
@@ -51,7 +54,7 @@ o = urlparse(cp.get("authority", "database"))
 if o.scheme == "mysql":
     import mysql.connector
     DATABASE_POOL = mysql.connector.pooling.MySQLConnectionPool(
-        pool_size = 3,
+        pool_size = 32,
         user=o.username,
         password=o.password,
         host=o.hostname,

certidude/mysqllog.py

@@ -0,0 +1,45 @@
+
+import logging
+import time
+ 
+class MySQLLogHandler(logging.Handler):
+ 
+    SQL_CREATE_TABLE = """CREATE TABLE IF NOT EXISTS log(
+        created datetime, facility varchar(30), level int,
+        severity varchar(10), message text, module varchar(20),
+        func varchar(20), lineno int, exception text, process int,
+        thread text, thread_name text)"""
+ 
+    SQL_INSERT_ENTRY = """insert into log( created, facility, level, severity,
+        message, module, func, lineno, exception, process, thread,
+        thread_name) values (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s);
+        """
+ 
+    def __init__(self, pool):
+        logging.Handler.__init__(self)
+        self.pool = pool
+        conn = self.pool.get_connection()
+        cur = conn.cursor()
+        cur.execute(self.SQL_CREATE_TABLE)
+        conn.commit()
+        cur.close()
+        conn.close()
+ 
+    def emit(self, record):
+        conn = self.pool.get_connection()
+        cur = conn.cursor()
+        cur.execute(self.SQL_INSERT_ENTRY, (
+            time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(record.created)),
+            record.name,
+            record.levelno,
+            record.levelname.lower(),
+            record.msg % record.args, record.module,
+            record.funcName,
+            record.lineno,
+            logging._defaultFormatter.formatException(record.exc_info) if record.exc_info else "",
+            record.process,
+            record.thread,
+            record.threadName))
+        conn.commit()
+        cur.close()
+        conn.close()

certidude/push.py

@@ -1,12 +1,18 @@
 
 import click
+import json
 import urllib.request
 from certidude import config
 
+
 def publish(event_type, event_data):
     """
     Publish event on push server
     """
+    if not isinstance(event_data, str):
+        from certidude.decorators import MyEncoder
+        event_data = json.dumps(event_data, cls=MyEncoder)
+
     url = config.PUSH_PUBLISH % config.PUSH_TOKEN
     click.echo("Posting event %s %s at %s, waiting for response..." % (repr(event_type), repr(event_data), repr(url)))
     notification = urllib.request.Request(
@@ -25,4 +31,7 @@ def publish(event_type, event_data):
             raise
     else:
         print("Push server returned:", response.code, body)
+    response.close()
+
+
 

certidude/static/authority.html

@@ -35,6 +35,19 @@
     </ul>
 </div>
 
+<div id="log">
+    <h1>Log</h1>
+    <p>
+        <input id="log_level_critical" type="checkbox" checked/> <label for="log_level_critical">Critical</label>
+        <input id="log_level_error" type="checkbox" checked/> <label for="log_level_error">Errors</label>
+        <input id="log_level_warning" type="checkbox" checked/> <label for="log_level_warning">Warnings</label>
+        <input id="log_level_info" type="checkbox" checked/> <label for="log_level_info">Info</label>
+        <input id="log_level_debug" type="checkbox"/> <label for="log_level_debug">Debug</label>
+    </p>
+    <ul id="log_entries">
+    </ul>
+</div>
+
 <div id="revoked">
     <h1>Revoked certificates</h1>
     <p>To fetch certificate revocation list:</p>

certidude/static/css/style.css

@@ -75,7 +75,6 @@ button:disabled, .button:disabled {
 
 footer {
     display: block;
-    color: #fff;
     text-align: center;
 }
 
@@ -84,10 +83,6 @@ a {
     color: #44c;
 }
 
-footer a {
-    color: #aaf;
-}
-
 html,body {
     margin: 0;
     padding: 0 0 1em 0;
@@ -143,6 +138,7 @@ pre {
 
 .container {
     max-width: 960px;
+    padding: 0 1em;
     margin: 0 auto;
 }
 
@@ -174,6 +170,19 @@ pre {
     text-decoration: none;
 }
 
+li span.icon {
+    background-size: 32px;
+    padding-left: 42px;
+    padding-top: 2px;
+    padding-bottom: 2px;
+}
+
+
+.icon.critical { background-image: url("../img/iconmonstr-error-4-icon.svg"); }
+.icon.error { background-image: url("../img/iconmonstr-error-4-icon.svg"); }
+.icon.warning { background-image: url("../img/iconmonstr-warning-6-icon.svg"); }
+.icon.info { background-image: url("../img/iconmonstr-info-6-icon.svg"); }
+
 
 .icon.revoke { background-image: url("../img/iconmonstr-x-mark-5-icon.svg"); }
 .icon.download { background-image: url("../img/iconmonstr-download-12-icon.svg"); }

certidude/static/img/iconmonstr-error-4-icon.svg

@@ -0,0 +1,12 @@
+<?xml version="1.0" encoding="utf-8"?>
+<!-- The icon can be used freely in both personal and commercial projects with no attribution required, but always appreciated.
+You may NOT sub-license, resell, rent, redistribute or otherwise transfer the icon without express written permission from iconmonstr.com -->
+<!DOCTYPE svg PUBLIC "-//W3C//DTD SVG 1.1//EN" "http://www.w3.org/Graphics/SVG/1.1/DTD/svg11.dtd">
+<svg version="1.1" xmlns="http://www.w3.org/2000/svg" xmlns:xlink="http://www.w3.org/1999/xlink" x="0px" y="0px"
+	 width="32px" height="32px" viewBox="0 0 512 512" enable-background="new 0 0 512 512" xml:space="preserve">
+<path id="error-4-icon" d="M324.76,90L422,187.24v137.52L324.76,422H187.24L90,324.76V187.24L187.24,90H324.76 M341.328,50H170.672
+	L50,170.672v170.656L170.672,462h170.656L462,341.328V170.672L341.328,50L341.328,50z M228.55,135.812h54.9v166.5h-54.9V135.812z
+	 M256,388.188c-16.362,0-29.625-13.264-29.625-29.625c0-16.362,13.263-29.627,29.625-29.627c16.361,0,29.625,13.265,29.625,29.627
+	C285.625,374.924,272.361,388.188,256,388.188z"/>
+</svg>
+

certidude/static/img/iconmonstr-info-6-icon.svg

@@ -0,0 +1,18 @@
+<?xml version="1.0" encoding="utf-8"?>
+<!-- The icon can be used freely in both personal and commercial projects with no attribution required, but always appreciated.
+You may NOT sub-license, resell, rent, redistribute or otherwise transfer the icon without express written permission from iconmonstr.com -->
+<!DOCTYPE svg PUBLIC "-//W3C//DTD SVG 1.1//EN" "http://www.w3.org/Graphics/SVG/1.1/DTD/svg11.dtd">
+<svg version="1.1" xmlns="http://www.w3.org/2000/svg" xmlns:xlink="http://www.w3.org/1999/xlink" x="0px" y="0px"
+	 width="32px" height="32px" viewBox="0 0 512 512" enable-background="new 0 0 512 512" xml:space="preserve">
+<path id="info-6-icon" d="M256,90.002c91.74,0,166,74.241,166,165.998c0,91.739-74.245,165.998-166,165.998
+	c-91.738,0-166-74.242-166-165.998C90,164.259,164.243,90.002,256,90.002 M256,50.002C142.229,50.002,50,142.228,50,256
+	c0,113.769,92.229,205.998,206,205.998c113.77,0,206-92.229,206-205.998C462,142.228,369.77,50.002,256,50.002L256,50.002z
+	 M252.566,371.808c-28.21,9.913-51.466-1.455-46.801-28.547c4.667-27.098,31.436-85.109,35.255-96.079
+	c3.816-10.97-3.502-13.977-11.346-9.513c-4.524,2.61-11.248,7.841-17.02,12.925c-1.601-3.223-3.852-6.906-5.542-10.433
+	c9.419-9.439,25.164-22.094,43.803-26.681c22.27-5.497,59.492,3.29,43.494,45.858c-11.424,30.34-19.503,51.276-24.594,66.868
+	c-5.088,15.598,0.955,18.868,9.863,12.791c6.959-4.751,14.372-11.214,19.806-16.226c2.515,4.086,3.319,5.389,5.806,10.084
+	C295.857,342.524,271.182,365.151,252.566,371.808z M311.016,184.127c-12.795,10.891-31.76,10.655-42.37-0.532
+	c-10.607-11.181-8.837-29.076,3.955-39.969c12.794-10.89,31.763-10.654,42.37,0.525
+	C325.577,155.337,323.809,173.231,311.016,184.127z"/>
+</svg>
+

certidude/static/img/iconmonstr-warning-6-icon.svg

@@ -0,0 +1,11 @@
+<?xml version="1.0" encoding="utf-8"?>
+<!-- The icon can be used freely in both personal and commercial projects with no attribution required, but always appreciated.
+You may NOT sub-license, resell, rent, redistribute or otherwise transfer the icon without express written permission from iconmonstr.com -->
+<!DOCTYPE svg PUBLIC "-//W3C//DTD SVG 1.1//EN" "http://www.w3.org/Graphics/SVG/1.1/DTD/svg11.dtd">
+<svg version="1.1" xmlns="http://www.w3.org/2000/svg" xmlns:xlink="http://www.w3.org/1999/xlink" x="0px" y="0px"
+	 width="32px" height="32px" viewBox="0 0 512 512" enable-background="new 0 0 512 512" xml:space="preserve">
+<path id="warning-6-icon" d="M239.939,231.352h32.121v97.421h-32.121V231.352z M256,379.019c-9.574,0-17.334-7.761-17.334-17.334
+	c0-9.574,7.76-17.335,17.334-17.335c9.573,0,17.334,7.761,17.334,17.335C273.334,371.258,265.573,379.019,256,379.019z M256,78.07
+	L50,434.873h412L256,78.07z M256,158.07l136.718,236.803H119.282L256,158.07z"/>
+</svg>
+

certidude/static/js/certidude.js

@@ -23,6 +23,20 @@ $(document).ready(function() {
                 console.log("Received server-sent event:", event);
             }
 
+            source.addEventListener("log-entry", function(e) {
+                var entry = JSON.parse(e.data);
+                console.info("Received log entry:", entry, "gonna prepend:", $("#log_level_" + entry.severity).prop("checked"));
+                if ($("#log_level_" + entry.severity).prop("checked")) {
+                    $("#log_entries").prepend(nunjucks.render("logentry.html", {
+                        entry: {
+                            created: new Date(entry.created).toLocaleString(),
+                            message: entry.message,
+                            severity: entry.severity
+                        }
+                    }));
+                }
+            });
+
             source.addEventListener("up-client", function(e) {
                 console.log("Adding security association:" + e.data);
                 var lease = JSON.parse(e.data);
@@ -92,6 +106,27 @@ $(document).ready(function() {
 
             $("#container").html(nunjucks.render('authority.html', { session: session, window: window }));
 
+
+            $.ajax({
+                method: "GET",
+                url: "/api/log/",
+                dataType: "json",
+                success:function(entries, status, xhr) {
+                    console.info("Got", entries.length, "log entries");
+                    for (var j = 0; j < entries.length; j++) {
+                        if ($("#log_level_" + entries[j].severity).prop("checked")) {
+                            $("#log_entries").append(nunjucks.render("logentry.html", {
+                                entry: {
+                                    created: new Date(entries[j].created).toLocaleString("et-EE"),
+                                    message: entries[j].message,
+                                    severity: entries[j].severity
+                                }
+                            }));
+                        }
+                    }
+                }
+            });
+
             $.ajax({
                 method: "GET",
                 url: "/api/lease/",

certidude/static/logentry.html

@@ -0,0 +1,5 @@
+<li id="log_entry_{{ entry.id }}" class="filterable">
+<span class="created monospace" style="float:right;">{{ entry.created }}</span>
+<span class="message icon {{ entry.severity }}">{{ entry.message }}</span>
+</li>
+