Merge pull request #50 from tgross/gh30_logging_improvements

Logging and exception handling improvements

Dockerfile

@@ -1,6 +1,6 @@
 FROM percona:5.6
 
-ENV CONTAINERPILOT_VER 2.4.0
+ENV CONTAINERPILOT_VER 2.4.1
 ENV CONTAINERPILOT file:///etc/containerpilot.json
 
 # By keeping a lot of discrete steps in a single RUN we can clean up after
@@ -19,6 +19,7 @@ RUN set -ex \
        PyMySQL==0.6.7 \
        python-Consul==0.4.7 \
        manta==2.5.0 \
+       mock==2.0.0 \
     # \
     # Add Consul from https://releases.hashicorp.com/consul \
     # \
@@ -31,7 +32,7 @@ RUN set -ex \
     # \
     # Add ContainerPilot and set its configuration file path \
     # \
-    && export CONTAINERPILOT_CHECKSUM=dbdad2cd8da8fe6128f8a2d1736f7b051ba70fe6 \
+    && export CONTAINERPILOT_CHECKSUM=198d96c8d7bfafb1ab6df96653c29701510b833c \
     && curl -Lvo /tmp/containerpilot.tar.gz "https://github.com/joyent/containerpilot/releases/download/${CONTAINERPILOT_VER}/containerpilot-${CONTAINERPILOT_VER}.tar.gz" \
     && echo "${CONTAINERPILOT_CHECKSUM}  /tmp/containerpilot.tar.gz" | sha1sum -c \
     && tar zxf /tmp/containerpilot.tar.gz -C /usr/local/bin \

bin/manage.py

@@ -38,27 +38,31 @@ class WaitTimeoutError(Exception):
     """ Exception raised when a timeout occurs. """
     pass
 
-def debug(fn):
+def debug(fn=None, name=None):
     """
     Function/method decorator to trace calls via debug logging.
     Is a pass-thru if we're not at LOG_LEVEL=DEBUG. Normally this
     would have a lot of perf impact but this application doesn't
     have significant throughput.
     """
-    @wraps(fn)
-    def wrapper(*args, **kwargs):
-        try:
-            # because we have concurrent processes running we want
-            # to tag each stack with an identifier for that process
-            arg = "[{}]".format(sys.argv[1])
-        except IndexError:
-            arg = "[pre_start]"
-        name = '{}{}{}'.format(arg, (len(inspect.stack()) * " "), fn.__name__)
-        log.debug('%s' % name)
-        out = apply(fn, args, kwargs)
-        log.debug('%s: %s', name, out)
-        return out
-    return wrapper
+    def _decorate(fn, *args, **kwargs):
+        @wraps(fn)
+        def wrapper(*args, **kwargs):
+            try:
+                # because we have concurrent processes running we want
+                # to tag each stack with an identifier for that process
+                arg = "[{}]".format(sys.argv[1])
+            except IndexError:
+                arg = "[pre_start]"
+            name = kwargs.get('name', fn.__name__)
+            log.debug('%s %s start', arg, name)
+            out = apply(fn, args, kwargs)
+            log.debug('%s %s end', arg, name)
+            return out
+        return wrapper
+    if fn:
+        return _decorate(fn)
+    return _decorate
 
 def get_environ_flag(key, default):
     """
@@ -294,23 +298,23 @@ def __init__(self, node):
 
         self.config['consul'] = '{}:8500'.format(get_consul_host())
         if get_environ_flag('CONSUL_AGENT', False):
-            _consul_host = '{}'.format(get_environ('CONSUL', 'consul'))
+            _consul_host = '{}:8500'.format(get_environ('CONSUL', 'consul'))
             cmd = self.config['coprocesses'][0]['command']
             host_cfg_idx = cmd.index('-retry-join') + 1
             cmd[host_cfg_idx] = _consul_host
             self.config['coprocesses'][0]['command'] = cmd
         else:
             self.config['coprocesses'] = []
 
-    @debug
+    @debug(name='ContainerPilot.update')
     def update(self):
         state = self.node.get_state()
         if state and self.config['services'][0]['name'] != state:
             self.config['services'][0]['name'] = state
             self.render()
             return True
 
-    @debug
+    @debug(name='ContainerPilot.render')
     def render(self):
         new_config = json.dumps(self.config)
         with open(self.path, 'w') as f:
@@ -510,8 +514,8 @@ def create_snapshot():
         log.info('snapshot completed, uploading to object store')
         manta_config.put_backup(backup_id, '/tmp/backup.tar')
 
-        log.debug('snapshot uploaded to {}/{}, setting LAST_BACKUP_KEY'
-                  ' in Consul'.format(manta_config.bucket, backup_id))
+        log.debug('snapshot uploaded to %s/%s, setting LAST_BACKUP_KEY'
+                  ' in Consul' % (manta_config.bucket, backup_id))
         consul.kv.put(LAST_BACKUP_KEY, backup_id)
 
         ctx = dict(user=config.repl_user,
@@ -657,6 +661,7 @@ def wait_for_connection(user='root', password=None, database=None, timeout=30):
         except pymysql.err.OperationalError:
             timeout = timeout - 1
             if timeout == 0:
+                # re-raise MySQL error
                 raise
             time.sleep(1)
 
@@ -1045,9 +1050,9 @@ def get_primary_node(timeout=10):
         except Exception as ex:
             timeout = timeout - 1
             time.sleep(1)
-    raise ex
-
+    raise WaitTimeoutError(ex)
 
+@debug
 def get_standby_node(timeout=10):
     while timeout > 0:
         try:
@@ -1060,7 +1065,7 @@ def get_standby_node(timeout=10):
         except Exception as ex:
             timeout = timeout - 1
             time.sleep(1)
-    raise ex
+    raise WaitTimeoutError(ex)
 
 def get_from_consul(key):
     """

docker-compose.yml

@@ -12,6 +12,7 @@ mysql:
     environment:
       - CONTAINERPILOT=file:///etc/containerpilot.json
       - CONSUL_AGENT=1
+      - LOG_LEVEL
 
 consul:
     image: progrium/consul:latest

etc/containerpilot.json

@@ -1,6 +1,9 @@
 {
   "consul": "{{ if .CONSUL_AGENT }}localhost{{ else }}{{ .CONSUL }}{{ end }}:8500",
   "preStart": "python /usr/local/bin/manage.py",
+  "logging": {
+    "level": "{{ if .LOG_LEVEL }}{{ .LOG_LEVEL }}{{ else }}INFO{{ end }}"
+  },
   "services": [
     {
       "name": "mysql",

local-compose.yml

@@ -6,6 +6,7 @@ mysql:
     environment:
       - CONSUL_AGENT=1
       - CONSUL=consul
+      - LOG_LEVEL
     links:
       - consul:consul
     ports:

makefile

@@ -28,10 +28,12 @@ TAG := $(BRANCH)-$(COMMIT)
 build:
 	docker build -t=autopilotpattern/mysql:$(TAG) .
 
+tag:
+	docker tag autopilotpattern/mysql:$(TAG) autopilotpattern/mysql:latest
+
 ## Pushes the application container image to the Docker Hub
-ship:
+ship: tag
 	docker push autopilotpattern/mysql:$(TAG)
-	docker tag autopilotpattern/mysql:$(TAG) autopilotpattern/mysql:latest
 	docker push autopilotpattern/mysql:latest
 
 
@@ -118,6 +120,15 @@ test-local-docker:
 		$(MANTA_CONFIG) \
 		$(LOCALRUN) $(PYTHON) tests.py
 
+## Run the unit tests inside the mysql container
+unit-test:
+	docker run -it --rm -w /usr/local/bin \
+		-e LOG_LEVEL=DEBUG \
+		-v $(shell pwd)/bin/manage.py:/usr/local/bin/manage.py \
+		-v $(shell pwd)/bin/test.py:/usr/local/bin/test.py \
+		autopilotpattern/mysql:$(TAG) \
+		python test.py
+
 shell:
 	docker run -it --rm \
 		-v /var/run/docker.sock:/var/run/docker.sock \

shippable.yml

@@ -13,6 +13,7 @@ build:
   # run integration tests using Docker Compose
   ci:
     - make build
+    - make unit-test
     - make test
 
   # send the containers to the Docker Hub

tests/Dockerfile

@@ -17,5 +17,6 @@ RUN git clone --depth 1 --single-branch -b master \
     && . $HOME/venv/3.5/bin/activate; python setup.py install
 
 COPY tests/tests.py /src/tests.py
+COPY bin/manage.py /src/manage.py
 COPY docker-compose.yml /src/docker-compose.yml
 COPY setup.sh /src/setup.sh

tests/tests.py

@@ -2,15 +2,18 @@
 import os
 from os.path import expanduser
 import random
-import re
 import subprocess
 import string
+import sys
 import time
 import unittest
 import uuid
 
 from testcases import AutopilotPatternTest, WaitTimeoutError
 
+UNIT_ONLY=False
+
+@unittest.skipIf(UNIT_ONLY, "running only unit tests")
 class MySQLStackTest(AutopilotPatternTest):
 
     project_name = 'my'
@@ -239,7 +242,8 @@ def parse_query(self, result):
         except IndexError as ex:
             self.fail(ex)
 
-
+# ------------------------------------------------
+# helper functions
 
 def gen_password():
     """
@@ -252,4 +256,8 @@ def gen_password():
 
 
 if __name__ == "__main__":
+
+    if len(sys.argv) > 1:
+        if sys.argv[1] == "unit":
+            UNIT_ONLY=True
     unittest.main()