fix(controller): write app event logs via logspout

Author: Kent Rancourt

controller/api/models.py

@@ -61,7 +61,7 @@ def _close_db_connections(*args, **kwargs):
 def log_event(app, msg, level=logging.INFO):
     # controller needs to know which app this log comes from
     logger.log(level, "{}: {}".format(app.id, msg))
-    app.log(msg)
+    app.log(msg, level)
 
 
 def validate_base64(value):
@@ -215,18 +215,15 @@ def _get_command(self, container_type):
             # handle special case for Dockerfile deployments
             return '' if container_type == 'cmd' else 'start {}'.format(container_type)
 
-    def log(self, message):
-        """Logs a message to the application's log file.
+    def log(self, message, level=logging.INFO):
+        """Logs a message in the context of this application.
 
-        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.
+        This prefixes log messages with an application "tag" that the customized deis-logspout will
+        be on the lookout for.  When it's seen, the message-- usually an application event of some
+        sort like releasing or scaling, will be considered as "belonging" to the application
+        instead of the controller and will be handled accordingly.
         """
-        with open(os.path.join(settings.DEIS_LOG_DIR, self.id + '.log'), 'a') as f:
-            msg = "{} deis[api]: {}\n".format(time.strftime(settings.DEIS_DATETIME_FORMAT),
-                                              message)
-            f.write(msg.encode('utf-8'))
+        logger.log(level, "[{}]: {}".format(self.id, message))
 
     def create(self, *args, **kwargs):
         """Create a new application with an initial config and release"""

controller/api/tests/test_app.py

@@ -7,6 +7,7 @@
 from __future__ import unicode_literals
 
 import json
+import logging
 import mock
 import os.path
 import requests
@@ -131,22 +132,18 @@ def test_app_actions(self):
         os.remove(path)
         # TODO: test run needs an initial build
 
-    def test_app_release_notes_in_logs(self):
+    @mock.patch('api.models.logger')
+    def test_app_release_notes_in_logs(self, mock_logger):
         """Verifies that an app's release summary is dumped into the logs."""
         url = '/v1/apps'
         body = {'id': 'autotest'}
         response = self.client.post(url, json.dumps(body), content_type='application/json',
                                     HTTP_AUTHORIZATION='token {}'.format(self.token))
         self.assertEqual(response.status_code, 201)
-        app_id = response.data['id']  # noqa
-        path = os.path.join(settings.DEIS_LOG_DIR, app_id + '.log')
-        url = '/v1/apps/{app_id}/logs'.format(**locals())
-        response = self.client.get(url,
-                                   HTTP_AUTHORIZATION='token {}'.format(self.token))
-        self.assertIn('autotest created initial release', response.data)
-        self.assertEqual(response.status_code, 200)
-        # delete file for future runs
-        os.remove(path)
+        # check app logs
+        exp_msg = "autotest created initial release"
+        exp_log_call = mock.call(logging.INFO, exp_msg)
+        mock_logger.log.has_calls(exp_log_call)
 
     def test_app_errors(self):
         app_id = 'autotest-errors'
@@ -202,7 +199,8 @@ def test_app_structure_is_valid_json(self):
         self.assertEqual(response.data['structure'], {"web": 1})
 
     @mock.patch('requests.post', mock_import_repository_task)
-    def test_admin_can_manage_other_apps(self):
+    @mock.patch('api.models.logger')
+    def test_admin_can_manage_other_apps(self, mock_logger):
         """Administrators of Deis should be able to manage all applications.
         """
         # log in as non-admin user and create an app
@@ -213,18 +211,15 @@ def test_admin_can_manage_other_apps(self):
         body = {'id': app_id}
         response = self.client.post(url, json.dumps(body), content_type='application/json',
                                     HTTP_AUTHORIZATION='token {}'.format(token))
-        app = App.objects.get(id=app_id)
         # log in as admin, check to see if they have access
         url = '/v1/apps/{}'.format(app_id)
         response = self.client.get(url,
                                    HTTP_AUTHORIZATION='token {}'.format(self.token))
         self.assertEqual(response.status_code, 200)
         # check app logs
-        url = '/v1/apps/{app_id}/logs'.format(**locals())
-        response = self.client.get(url,
-                                   HTTP_AUTHORIZATION='token {}'.format(self.token))
-        self.assertEqual(response.status_code, 200)
-        self.assertIn('autotest2 created initial release', response.data)
+        exp_msg = "autotest2 created initial release"
+        exp_log_call = mock.call(logging.INFO, exp_msg)
+        mock_logger.log.has_calls(exp_log_call)
         # TODO: test run needs an initial build
         # delete the app
         url = '/v1/apps/{}'.format(app_id)

controller/api/tests/test_config.py

@@ -8,6 +8,7 @@
 from __future__ import unicode_literals
 
 import json
+import logging
 import mock
 import requests
 
@@ -569,7 +570,8 @@ def test_app_healthcheck_good(self):
     @mock.patch('requests.get', mock_status_not_found)
     @mock.patch('api.models.get_etcd_client', lambda func: func)
     @mock.patch('time.sleep', lambda func: func)
-    def test_app_healthcheck_bad(self):
+    @mock.patch('api.models.logger')
+    def test_app_healthcheck_bad(self, mock_logger):
         """
         If a user deploys an app with a config value set for HEALTHCHECK_URL, the controller
         should check that the application responds with a 200 OK. If it's down, the app should be
@@ -583,10 +585,16 @@ def test_app_healthcheck_bad(self):
         # check that only the build and initial release exist
         self.assertEqual(self.app.release_set.latest().version, 2)
         # assert that the reason why the containers failed was because
-        # they failed the health check 4 times
-        self.assertEqual(
-            self.app.logs().count("app failed health check (got '404', expected: '200')"),
-            4)
+        # they failed the health check 4 times; we do this by looking
+        # at logs-- there may be a better way
+        exp_msg = "{}: app failed health check (got '404', expected: '200'); trying again in 0.0 \
+seconds".format(self.app.id)
+        exp_log_call = mock.call(logging.WARNING, exp_msg)
+        log_calls = mock_logger.log.mock_calls
+        self.assertEqual(log_calls.count(exp_log_call), 3)
+        exp_msg = "{}: app failed health check (got '404', expected: '200')".format(self.app.id)
+        exp_log_call = mock.call(logging.WARNING, exp_msg)
+        self.assertEqual(log_calls.count(exp_log_call), 1)
 
     @mock.patch('requests.get', mock_status_not_found)
     @mock.patch('api.models.get_etcd_client', lambda func: func)

logspout/logspout.go

@@ -64,7 +64,7 @@ func syslogStreamer(target Target, types []string, logstream chan *Log) {
 		if typestr != ",," && !strings.Contains(typestr, logline.Type) {
 			continue
 		}
-		tag, pid := getLogName(logline.Name)
+		tag, pid, data := getLogParts(logline)
 		var conn net.Conn
 		if strings.EqualFold(target.Protocol, "tcp") {
 			addr, err := net.ResolveTCPAddr("tcp", target.Addr)
@@ -89,25 +89,34 @@ func syslogStreamer(target Target, types []string, logstream chan *Log) {
 			time.Now().Format(getopt("DATETIME_FORMAT", dtime.DeisDatetimeFormat)),
 			tag,
 			pid,
-			logline.Data)
+			data)
 		assert(err, "syslog")
 	}
 }
 
-// getLogName returns a custom tag and PID for containers that
+// getLogParts returns a custom tag and PID for containers that
 // match Deis' specific application name format. Otherwise,
-// it returns the original name and 1 as the PID.
-func getLogName(name string) (string, string) {
+// it returns the original name and 1 as the PID.  Additionally,
+// it returns log data.  The function is also smart enough to
+// detect when a leading tag in the log data represents an attempt
+// by the controller to log an application event.
+func getLogParts(logline *Log) (string, string, string) {
 	// example regex that should match: go_v2.web.1
-	match := getMatch(`(^[a-z0-9-]+)_(v[0-9]+)\.([a-z-_]+\.[0-9]+)$`, name)
+	match := getMatch(`(^[a-z0-9-]+)_(v[0-9]+)\.([a-z-_]+\.[0-9]+)$`, logline.Name)
 	if match != nil {
-		return match[1], match[3]
+		return match[1], match[3], logline.Data
 	}
-	match = getMatch(`^k8s_([a-z0-9-]+)-[a-z]+\.[\da-f]+_[a-z0-9-]+-([a-z]+-[\da-z]*)_`, name)
+	match = getMatch(`^k8s_([a-z0-9-]+)-[a-z]+\.[\da-f]+_[a-z0-9-]+-([a-z]+-[\da-z]*)_`, logline.Name)
 	if match != nil {
-		return match[1], match[2]
+		return match[1], match[2], logline.Data
 	}
-	return name, "1"
+	if logline.Name == "deis-controller" {
+		data_match := getMatch(`^[A-Z]+ \[([a-z0-9-]+)\]: (.*)`, logline.Data)
+		if data_match != nil {
+			return data_match[1], "deis-controller", data_match[2]
+		}
+	}
+	return logline.Name, "1", logline.Data
 }
 
 func getMatch(regex string, name string) []string {