feat(controller): pipe release notes to app logs

Whenever a release is created for an application, its logs will now
also be seen in `deis logs`. The log pattern follows the same syntax
as Heroku's logs:

    2014-08-25T20:23:53.275002+00:00 heroku[api]: Enable Logplex by me@bacongobbler.com
    2014-08-25T20:23:53.275063+00:00 heroku[api]: Release v2 created by me@bacongobbler.com

The log syntax coming from the controller looks like so in the app logs:

    2014-08-25 14:25:50 deis[api]: bacongobbler created initial release

Which follows the same syntax as our app logs:

    2014-08-25 14:25:50 island-larkspur[web.1]: listening on port 5000...

Author: Matthew Fisher

controller/api/models.py

@@ -11,6 +11,7 @@
 import os
 import re
 import subprocess
+import time
 
 from celery.canvas import group
 from django.conf import settings
@@ -162,6 +163,19 @@ def __str__(self):
     def url(self):
         return self.id + '.' + self.cluster.domain
 
+    def log(self, message):
+        """Logs a message to the application's log file.
+
+        This is a workaround for how Django interacts with Python's logging module. Each app
+        needs its own FileHandler instance so it can write to its own log file. That won't work in
+        Django's case because logging is set up before you run the server and it disables all
+        existing logging configurations.
+        """
+        with open(os.path.join(settings.DEIS_LOG_DIR, self.id + '.log'), 'a') as f:
+            f.write('{} deis[api]: {}\n'.format(
+                time.strftime('%Y-%m-%d %H:%M:%S'),
+                message))
+
     def create(self, *args, **kwargs):
         config = Config.objects.create(owner=self.owner, app=self)
         build = Build.objects.create(owner=self.owner, app=self, image=settings.DEFAULT_BUILD)
@@ -209,7 +223,7 @@ def scale(self, **kwargs):  # noqa
             if container_type not in available_process_types:
                 raise EnvironmentError(
                     'Container type {} does not exist in application'.format(container_type))
-        msg = 'Containers scaled ' + ' '.join(
+        msg = 'containers scaled ' + ' '.join(
             "{}={}".format(k, v) for k, v in requested_containers.items())
         # iterate and scale by container type (web, worker, etc)
         changed = False
@@ -245,6 +259,7 @@ def scale(self, **kwargs):  # noqa
                 subtasks.append(tasks.stop_containers.s(to_remove))
             group(*subtasks).apply_async().join()
             log_event(self, msg)
+            self.log(msg)
         return changed
 
     def logs(self):
@@ -258,7 +273,9 @@ def logs(self):
     def run(self, command):
         """Run a one-off command in an ephemeral app container."""
         # TODO: add support for interactive shell
-        log_event(self, "deis run '{}'".format(command))
+        msg = "deis run '{}'".format(command)
+        log_event(self, msg)
+        self.log(msg)
         c_num = max([c.num for c in self.container_set.filter(type='admin')] or [0]) + 1
         c = Container.objects.create(owner=self.owner,
                                      app=self,
@@ -654,28 +671,36 @@ def __str__(self):
 def _log_build_created(**kwargs):
     if kwargs.get('created'):
         build = kwargs['instance']
-        log_event(build.app, "Build {} created".format(build))
+        log_event(build.app, "build {} created".format(build))
 
 
 def _log_release_created(**kwargs):
     if kwargs.get('created'):
         release = kwargs['instance']
-        log_event(release.app, "Release {} created".format(release))
+        log_event(release.app, "release {} created".format(release))
+        # append release lifecycle logs to the app
+        release.app.log(release.summary)
 
 
 def _log_config_updated(**kwargs):
     config = kwargs['instance']
-    log_event(config.app, "Config {} updated".format(config))
+    log_event(config.app, "config {} updated".format(config))
 
 
 def _log_domain_added(**kwargs):
     domain = kwargs['instance']
-    log_event(domain.app, "Domain {} added".format(domain))
+    msg = "domain {} added".format(domain)
+    log_event(domain.app, msg)
+    # adding a domain does not create a release, so we have to log here
+    domain.app.log(msg)
 
 
 def _log_domain_removed(**kwargs):
     domain = kwargs['instance']
-    log_event(domain.app, "Domain {} removed".format(domain))
+    msg = "domain {} removed".format(domain)
+    log_event(domain.app, msg)
+    # adding a domain does not create a release, so we have to log here
+    domain.app.log(msg)
 
 
 def _etcd_publish_key(**kwargs):

controller/api/tests/test_app.py

@@ -77,14 +77,15 @@ def test_app_actions(self):
         if not os.path.exists(settings.DEIS_LOG_DIR):
             os.mkdir(settings.DEIS_LOG_DIR)
         path = os.path.join(settings.DEIS_LOG_DIR, app_id + '.log')
+        # HACK: remove app lifecycle logs
         if os.path.exists(path):
             os.remove(path)
         url = '/api/apps/{app_id}/logs'.format(**locals())
         response = self.client.post(url)
         self.assertEqual(response.status_code, 204)
         self.assertEqual(response.data, 'No logs for {}'.format(app_id))
         # write out some fake log data and try again
-        with open(path, 'w') as f:
+        with open(path, 'a') as f:
             f.write(FAKE_LOG_DATA)
         response = self.client.post(url)
         self.assertEqual(response.status_code, 200)
@@ -95,6 +96,23 @@ def test_app_actions(self):
         response = self.client.post(url, json.dumps(body), content_type='application/json')
         self.assertEqual(response.status_code, 200)
         self.assertEqual(response.data[0], 0)
+        # delete file for future runs
+        os.remove(path)
+
+    def test_app_release_notes_in_logs(self):
+        """Verifies that an app's release summary is dumped into the logs."""
+        url = '/api/apps'
+        body = {'cluster': 'autotest', 'id': 'autotest'}
+        response = self.client.post(url, json.dumps(body), content_type='application/json')
+        self.assertEqual(response.status_code, 201)
+        app_id = response.data['id']  # noqa
+        path = os.path.join(settings.DEIS_LOG_DIR, app_id + '.log')
+        url = '/api/apps/{app_id}/logs'.format(**locals())
+        response = self.client.post(url)
+        self.assertIn('autotest created initial release', response.data)
+        self.assertEqual(response.status_code, 200)
+        # delete file for future runs
+        os.remove(path)
 
     def test_app_errors(self):
         cluster_id, app_id = 'autotest', 'autotest-errors'

tests/apps_test.go

@@ -74,7 +74,8 @@ func appsListTest(t *testing.T, params *utils.DeisTestConfig, notflag bool) {
 
 func appsLogsTest(t *testing.T, params *utils.DeisTestConfig) {
 	cmd := appsLogsCmd
-	utils.Execute(t, cmd, params, true, "204 NO CONTENT")
+	// test for application lifecycle logs
+	utils.Execute(t, cmd, params, false, "204 NO CONTENT")
 	if err := utils.Chdir(params.ExampleApp); err != nil {
 		t.Fatal(err)
 	}