launchpad-reviewers team mailing list archive

["Thiago F. Pappacena" <pappacena@xxxxxxxxx>]

Thiago F. Pappacena has proposed merging ~pappacena/turnip:fork-verbosiry into turnip:master.

Commit message:
Making celery a bit more verbose, and adding logs for fork operation

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)

For more details, see:
https://code.launchpad.net/~pappacena/turnip/+git/turnip/+merge/391850
-- 
Your team Launchpad code reviewers is requested to review the proposed merge of ~pappacena/turnip:fork-verbosiry into turnip:master.

diff --git a/Makefile b/Makefile
index 628d4c8..ff5d64e 100644
--- a/Makefile
+++ b/Makefile
@@ -109,7 +109,7 @@ run-pack: $(ENV)
 
 run-worker: $(ENV)
 	$(CELERY) -A turnip.tasks worker \
-		--loglevel=info \
+		--loglevel=debug \
 		--concurrency=20 \
 		--pool=gevent
 
diff --git a/charm/turnip-celery/templates/turnip-celery.service.j2 b/charm/turnip-celery/templates/turnip-celery.service.j2
index e6a2132..a075e6b 100644
--- a/charm/turnip-celery/templates/turnip-celery.service.j2
+++ b/charm/turnip-celery/templates/turnip-celery.service.j2
@@ -16,7 +16,7 @@ Environment=TURNIP_LOG_DIR={{ logs_dir }}
 Environment=CELERY_BROKER={{ celery_broker }}
 Environment=VIRTINFO_ENDPOINT={{ virtinfo_endpoint }}
 Environment=VIRTINFO_TIMEOUT={{ virtinfo_timeout }}
-ExecStart={{ venv_dir }}/bin/celery -A turnip.tasks worker --logfile={{ logs_dir }}/turnip-celery.log --pool=gevent
+ExecStart={{ venv_dir }}/bin/celery -A turnip.tasks worker --logfile={{ logs_dir }}/turnip-celery.log --loglevel=DEBUG --pool=gevent
 ExecReload=/bin/kill -s HUP $MAINPID
 ExecStop=/bin/kill -s TERM $MAINPID
 LimitNOFILE=1048576
diff --git a/turnip/api/store.py b/turnip/api/store.py
index b00c83b..28b7b45 100644
--- a/turnip/api/store.py
+++ b/turnip/api/store.py
@@ -364,8 +364,15 @@ def init_and_confirm_repo(untranslated_path, repo_path, clone_from=None,
     xmlrpc_proxy = TimeoutServerProxy(
         xmlrpc_endpoint, timeout=xmlrpc_timeout, allow_none=True)
     try:
+        logger.info(
+            "Initializing and confirming repository creation: "
+            "%s; %s; %s; %s; %s", repo_path, clone_from, clone_refs,
+            alternate_repo_paths, is_bare)
         init_repo(
             repo_path, clone_from, clone_refs, alternate_repo_paths, is_bare)
+        logger.debug(
+            "Confirming repository creation: %s; %s",
+            untranslated_path, xmlrpc_auth_params)
         xmlrpc_proxy.confirmRepoCreation(untranslated_path, xmlrpc_auth_params)
     except Exception as e:
         logger.error("Error creating repository at %s: %s", repo_path, e)
@@ -373,6 +380,9 @@ def init_and_confirm_repo(untranslated_path, repo_path, clone_from=None,
             delete_repo(repo_path)
         except IOError as e:
             logger.error("Error deleting repository at %s: %s", repo_path, e)
+        logger.debug(
+            "Aborting repository creation: %s; %s",
+            untranslated_path, xmlrpc_auth_params)
         xmlrpc_proxy.abortRepoCreation(untranslated_path, xmlrpc_auth_params)
 
 
diff --git a/turnip/api/tests/test_api.py b/turnip/api/tests/test_api.py
index 5375a80..0eb9305 100644
--- a/turnip/api/tests/test_api.py
+++ b/turnip/api/tests/test_api.py
@@ -8,6 +8,7 @@ from __future__ import print_function, unicode_literals
 import base64
 from datetime import timedelta, datetime
 import os
+import re
 import subprocess
 from textwrap import dedent
 import time
@@ -1047,6 +1048,44 @@ class AsyncRepoCreationAPI(TestCase, ApiRepoStoreMixin):
             mock.ANY, new_repo_path, {"user": "+launchpad-services"})],
             self.virtinfo.xmlrpc_confirmRepoCreation.call_args_list)
 
+    def assertContainsLog(self, pattern, log_lines):
+        for line in log_lines:
+            if re.match(pattern, line):
+                return
+        self.fail("'%s' is not in any log line" % pattern)
+
+    def test_celery_log_messages(self):
+        logdir = self.useFixture(TempDir()).path
+        logfile = os.path.join(logdir, "celery.log")
+        self.useFixture(CeleryWorkerFixture(logfile=logfile, loglevel="debug"))
+
+        self.virtinfo.xmlrpc_confirmRepoCreation = mock.Mock(return_value=None)
+        self.virtinfo.xmlrpc_abortRepoCreation = mock.Mock(return_value=None)
+
+        factory = RepoFactory(self.repo_store, num_commits=2)
+        factory.build()
+        new_repo_path = uuid.uuid1().hex
+        self.app.post_json('/repo', {
+            'async': True,
+            'repo_path': new_repo_path,
+            'clone_from': self.repo_path,
+            'clone_refs': True})
+
+        self.assertRepositoryCreatedAsynchronously(new_repo_path)
+
+        # Read the log content
+        with open(logfile, 'r') as fd:
+            log_lines = fd.read().split('\n')
+        self.assertContainsLog(
+            ".*INFO.*Received task: turnip.api.store.init_and_confirm_repo.*",
+            log_lines)
+        self.assertContainsLog(
+            ".*INFO.*Initializing and confirming repository creation:.*",
+            log_lines)
+        self.assertContainsLog(
+            ".*DEBUG.*Confirming repository creation:.*",
+            log_lines)
+
 
 if __name__ == '__main__':
     unittest.main()
diff --git a/turnip/tests/tasks.py b/turnip/tests/tasks.py
index 5b2e0b3..d3e065a 100644
--- a/turnip/tests/tasks.py
+++ b/turnip/tests/tasks.py
@@ -29,7 +29,8 @@ class CeleryWorkerFixture(fixtures.Fixture):
     """
     _worker_proc = None
 
-    def __init__(self, loglevel="error", force_restart=True, env=None):
+    def __init__(self, loglevel="info", logfile=None,
+                 force_restart=True, env=None):
         """
         Build a celery worker for test cases.
 
@@ -42,6 +43,7 @@ class CeleryWorkerFixture(fixtures.Fixture):
         """
         self.force_restart = force_restart
         self.loglevel = loglevel
+        self.logfile = logfile
         self.env = env
 
     def startCeleryWorker(self):
@@ -58,6 +60,8 @@ class CeleryWorkerFixture(fixtures.Fixture):
             '--concurrency=20',
             '--broker=%s' % BROKER_URL,
             '--loglevel=%s' % self.loglevel]
+        if self.logfile:
+            cmd += ["--logfile=%s" % self.logfile]
 
         # Send to the subprocess, as env variables, the same configurations we
         # are currently using.