Merge pull request deis#4502 from krancour/logger-rewrite

chore(logger): refactor-- also includes new features

controller/api/models.py

@@ -10,9 +10,7 @@
 import etcd
 import importlib
 import logging
-import os
 import re
-import subprocess
 import time
 from threading import Thread
 
@@ -251,9 +249,14 @@ def restart(self, **kwargs):
 
     def _clean_app_logs(self):
         """Delete application logs stored by the logger component"""
-        path = os.path.join(settings.DEIS_LOG_DIR, self.id + '.log')
-        if os.path.exists(path):
-            os.remove(path)
+        try:
+            url = 'http://{}:{}/{}/'.format(settings.LOGGER_HOST, settings.LOGGER_PORT, self.id)
+            requests.delete(url)
+        except Exception as e:
+            # Ignore errors deleting application logs.  An error here should not interfere with
+            # the overall success of deleting an application, but we should log it.
+            err = 'Error deleting existing application logs: {}'.format(e)
+            log_event(self, err, logging.WARNING)
 
     def scale(self, user, structure):  # noqa
         """Scale containers up or down to match requested structure."""
@@ -518,11 +521,24 @@ def _default_scale(self, user, release):
 
     def logs(self, log_lines=str(settings.LOG_LINES)):
         """Return aggregated log data for this application."""
-        path = os.path.join(settings.DEIS_LOG_DIR, self.id + '.log')
-        if not os.path.exists(path):
+        try:
+            url = "http://{}:{}/{}?log_lines={}".format(settings.LOGGER_HOST, settings.LOGGER_PORT,
+                                                        self.id, log_lines)
+            r = requests.get(url)
+        # Handle HTTP request errors
+        except requests.exceptions.RequestException as e:
+            logger.error("Error accessing deis-logger using url '{}': {}".format(url, e))
+            raise e
+        # Handle logs empty or not found
+        if r.status_code == 204 or r.status_code == 404:
+            logger.info("GET {} returned a {} status code".format(url, r.status_code))
             raise EnvironmentError('Could not locate logs')
-        data = subprocess.check_output(['tail', '-n', log_lines, path])
-        return data
+        # Handle unanticipated status codes
+        if r.status_code != 200:
+            logger.error("Error accessing deis-logger: GET {} returned a {} status code"
+                         .format(url, r.status_code))
+            raise EnvironmentError('Error accessing deis-logger')
+        return r.content
 
     def run(self, user, command):
         """Run a one-off command in an ephemeral app container."""

controller/api/tests/__init__.py

@@ -1,9 +1,7 @@
 
 from __future__ import unicode_literals
 import logging
-import os
 
-from django.conf import settings
 from django.test.client import RequestFactory, Client
 from django.test.simple import DjangoTestSuiteRunner
 import requests
@@ -40,9 +38,6 @@ def run_tests(self, test_labels, extra_tests=None, **kwargs):
         """Run tests with all but critical log messages disabled."""
         # hide any log messages less than critical
         logging.disable(logging.CRITICAL)
-        # also, create the log directory
-        if not os.path.exists(settings.DEIS_LOG_DIR):
-            os.makedirs(settings.DEIS_LOG_DIR)
         return super(SilentDjangoTestSuiteRunner, self).run_tests(
             test_labels, extra_tests, **kwargs)
 

controller/api/tests/test_app.py

@@ -9,7 +9,7 @@
 import json
 import logging
 import mock
-import os.path
+import requests
 
 from django.conf import settings
 from django.contrib.auth.models import User
@@ -89,40 +89,49 @@ def test_app_override_id(self):
         self.assertContains(response, 'This field must be unique.', status_code=400)
         return response
 
-    def test_app_actions(self):
+    @mock.patch('requests.get')
+    def test_app_actions(self, mock_get):
         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
-        # test logs
-        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 = '/v1/apps/{app_id}/logs'.format(**locals())
-        response = self.client.get(url,
-                                   HTTP_AUTHORIZATION='token {}'.format(self.token))
+
+        # test logs - 204 from deis-logger
+        mock_response = mock.Mock()
+        mock_response.status_code = 204
+        mock_get.return_value = mock_response
+        url = "/v1/apps/{app_id}/logs".format(**locals())
+        response = self.client.get(url, HTTP_AUTHORIZATION="token {}".format(self.token))
         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, 'a') as f:
-            f.write(FAKE_LOG_DATA)
-        response = self.client.get(url,
-                                   HTTP_AUTHORIZATION='token {}'.format(self.token))
+        self.assertEqual(response.data, "No logs for {}".format(app_id))
+
+        # test logs - 404 from deis-logger
+        mock_response.status_code = 404
+        response = self.client.get(url, HTTP_AUTHORIZATION="token {}".format(self.token))
+        self.assertEqual(response.status_code, 204)
+        self.assertEqual(response.data, "No logs for {}".format(app_id))
+
+        # test logs - unanticipated status code from deis-logger
+        mock_response.status_code = 400
+        response = self.client.get(url, HTTP_AUTHORIZATION="token {}".format(self.token))
+        self.assertEqual(response.status_code, 500)
+        self.assertEqual(response.data, "Error accessing logs for {}".format(app_id))
+
+        # test logs - success accessing deis-logger
+        mock_response.status_code = 200
+        mock_response.content = FAKE_LOG_DATA
+        response = self.client.get(url, HTTP_AUTHORIZATION="token {}".format(self.token))
         self.assertEqual(response.status_code, 200)
         self.assertEqual(response.data, FAKE_LOG_DATA)
 
-        # test with log_lines
-        response = self.client.get(url + "?log_lines=1",
-                                   HTTP_AUTHORIZATION='token {}'.format(self.token))
-        self.assertEqual(response.status_code, 200)
-        self.assertEqual(response.data, FAKE_LOG_DATA.splitlines(True)[4])
+        # test logs - HTTP request error while accessing deis-logger
+        mock_get.side_effect = requests.exceptions.RequestException('Boom!')
+        response = self.client.get(url, HTTP_AUTHORIZATION="token {}".format(self.token))
+        self.assertEqual(response.status_code, 500)
+        self.assertEqual(response.data, "Error accessing logs for {}".format(app_id))
 
-        os.remove(path)
         # TODO: test run needs an initial build
 
     @mock.patch('api.models.logger')

controller/api/views.py

@@ -16,6 +16,8 @@
 
 from api import authentication, models, permissions, serializers, viewsets
 
+import requests
+
 
 class UserRegistrationViewSet(GenericViewSet,
                               mixins.CreateModelMixin):
@@ -208,10 +210,19 @@ def logs(self, request, **kwargs):
             return Response(app.logs(request.query_params.get('log_lines',
                                      str(settings.LOG_LINES))),
                             status=status.HTTP_200_OK, content_type='text/plain')
-        except EnvironmentError:
-            return Response("No logs for {}".format(app.id),
-                            status=status.HTTP_204_NO_CONTENT,
+        except requests.exceptions.RequestException:
+            return Response("Error accessing logs for {}".format(app.id),
+                            status=status.HTTP_500_INTERNAL_SERVER_ERROR,
                             content_type='text/plain')
+        except EnvironmentError as e:
+            if e.message == 'Error accessing deis-logger':
+                return Response("Error accessing logs for {}".format(app.id),
+                                status=status.HTTP_500_INTERNAL_SERVER_ERROR,
+                                content_type='text/plain')
+            else:
+                return Response("No logs for {}".format(app.id),
+                                status=status.HTTP_204_NO_CONTENT,
+                                content_type='text/plain')
 
     def run(self, request, **kwargs):
         app = self.get_object()

controller/conf.d/confd_settings.toml

@@ -11,5 +11,6 @@ keys = [
   "/deis/domains",
   "/deis/platform",
   "/deis/scheduler",
+  "/deis/logs",
 ]
 reload_cmd = "/app/bin/reload"

controller/deis/settings.py

@@ -280,7 +280,6 @@
 ETCD_HOST, ETCD_PORT = os.environ.get('ETCD', '127.0.0.1:4001').split(',')[0].split(':')
 
 # default deis settings
-DEIS_LOG_DIR = os.path.abspath(os.path.join(__file__, '..', '..', 'logs'))
 LOG_LINES = 1000
 TEMPDIR = tempfile.mkdtemp(prefix='deis')
 DEIS_DOMAIN = 'deisapp.local'
@@ -307,6 +306,10 @@
 REGISTRY_HOST = 'localhost'
 REGISTRY_PORT = 5000
 
+# logger settings
+LOGGER_HOST = 'localhost'
+LOGGER_PORT = 8088
+
 # check if we can register users with `deis register`
 REGISTRATION_ENABLED = True
 

controller/templates/confd_settings.py

@@ -43,8 +43,7 @@
     }
 }
 
-# move log directory out of /app/deis
-DEIS_LOG_DIR = '/data/logs'
+LOGGER_HOST = '{{ getv "/deis/logs/host"}}'
 
 {{ if exists "/deis/controller/registrationMode" }}
 REGISTRATION_MODE = '{{ getv "/deis/controller/registrationMode" }}'

controller/tests/controller_test.go

@@ -18,6 +18,7 @@ func TestController(t *testing.T) {
 		"/deis/registry/host",
 		"/deis/registry/port",
 		"/deis/platform/domain",
+		"/deis/logs/host",
 	}
 	setdir := []string{
 		"/deis/controller",

deisctl/cmd/cmd.go

@@ -21,7 +21,7 @@ import (
 const (
 	// PlatformCommand is shorthand for "all the Deis components."
 	PlatformCommand string = "platform"
-	// StatelessPlatformCommand is shorthand for the components except store-*, database, and logger.
+	// StatelessPlatformCommand is shorthand for the components except store-* and database.
 	StatelessPlatformCommand string = "stateless-platform"
 	swarm                    string = "swarm"
 	mesos                    string = "mesos"
@@ -142,10 +142,8 @@ func startDefaultServices(b backend.Backend, stateless bool, wg *sync.WaitGroup,
 
 	// start logging subsystem first to collect logs from other components
 	fmt.Fprintln(out, "Logging subsystem...")
-	if !stateless {
-		b.Start([]string{"logger"}, wg, out, err)
-		wg.Wait()
-	}
+	b.Start([]string{"logger"}, wg, out, err)
+	wg.Wait()
 	b.Start([]string{"logspout"}, wg, out, err)
 	wg.Wait()
 
@@ -319,11 +317,7 @@ func installDefaultServices(b backend.Backend, stateless bool, wg *sync.WaitGrou
 	}
 
 	fmt.Fprintln(out, "Logging subsystem...")
-	if stateless {
-		b.Create([]string{"logspout"}, wg, out, err)
-	} else {
-		b.Create([]string{"logger", "logspout"}, wg, out, err)
-	}
+	b.Create([]string{"logger", "logspout"}, wg, out, err)
 	wg.Wait()
 
 	fmt.Fprintln(out, "Control plane...")

deisctl/cmd/cmd_test.go

@@ -262,7 +262,7 @@ func TestStartStatelessPlatform(t *testing.T) {
 	t.Parallel()
 
 	b := backendStub{}
-	expected := []string{"logspout", "registry@*", "controller",
+	expected := []string{"logger", "logspout", "registry@*", "controller",
 		"builder", "publisher", "router@*", "registry@*", "controller",
 		"builder", "publisher", "router@*"}
 
@@ -575,7 +575,7 @@ func TestInstallStatelessPlatform(t *testing.T) {
 	b := backendStub{}
 	cb := mock.ConfigBackend{}
 
-	expected := []string{"logspout", "registry@1",
+	expected := []string{"logger", "logspout", "registry@1",
 		"controller", "builder", "publisher", "router@1", "router@2", "router@3"}
 
 	Install([]string{"stateless-platform"}, &b, &cb, fakeCheckKeys)

deisctl/units/deis-controller.service

@@ -1,15 +1,14 @@
 [Unit]
 Description=deis-controller
 Requires=fleet.socket
-Wants=deis-store-volume.service
-After=fleet.socket deis-store-volume.service
+After=fleet.socket
 
 [Service]
 EnvironmentFile=/etc/environment
 TimeoutStartSec=20m
 ExecStartPre=/bin/sh -c "IMAGE=`/run/deis/bin/get_image /deis/controller` && docker history $IMAGE >/dev/null 2>&1 || docker pull $IMAGE"
 ExecStartPre=/bin/sh -c "docker inspect deis-controller >/dev/null 2>&1 && docker rm -f deis-controller || true"
-ExecStart=/bin/sh -c "IMAGE=`/run/deis/bin/get_image /deis/controller` && docker run --name deis-controller --rm -p 8000:8000 -e EXTERNAL_PORT=8000 -e HOST=$COREOS_PRIVATE_IPV4 -v /var/run/fleet.sock:/var/run/fleet.sock -v /var/lib/deis/store:/data $IMAGE"
+ExecStart=/bin/sh -c "IMAGE=`/run/deis/bin/get_image /deis/controller` && docker run --name deis-controller --rm -p 8000:8000 -e EXTERNAL_PORT=8000 -e HOST=$COREOS_PRIVATE_IPV4 -v /var/run/fleet.sock:/var/run/fleet.sock $IMAGE"
 ExecStop=-/usr/bin/docker stop deis-controller
 Restart=on-failure
 RestartSec=5

deisctl/units/deis-logger.service

@@ -1,14 +1,14 @@
 [Unit]
 Description=deis-logger
-Requires=deis-store-volume.service
+Wants=deis-store-volume.service
 After=deis-store-volume.service
 
 [Service]
 EnvironmentFile=/etc/environment
 TimeoutStartSec=20m
 ExecStartPre=/bin/sh -c "IMAGE=`/run/deis/bin/get_image /deis/logger` && docker history $IMAGE >/dev/null 2>&1 || docker pull $IMAGE"
 ExecStartPre=/bin/sh -c "docker inspect deis-logger >/dev/null 2>&1 && docker rm -f deis-logger || true"
-ExecStart=/bin/sh -c "IMAGE=`/run/deis/bin/get_image /deis/logger` && docker run --name deis-logger --rm -p 514:514/udp -e EXTERNAL_PORT=514 -e HOST=$COREOS_PRIVATE_IPV4 -v /var/lib/deis/store:/data $IMAGE"
+ExecStart=/bin/sh -c "IMAGE=`/run/deis/bin/get_image /deis/logger` && docker run --name deis-logger --rm -p 8088:8088/tcp -p 514:514/udp -e EXTERNAL_PORT=514 -e HOST=$COREOS_PRIVATE_IPV4 -v /var/lib/deis/store:/data $IMAGE"
 ExecStop=-/usr/bin/docker stop deis-logger
 Restart=on-failure
 RestartSec=5

docs/customizing_deis/controller_settings.rst

@@ -30,6 +30,7 @@ setting                                  description
 /deis/controller/unitHostname            See `Unit hostname`_. (default: "default")
 /deis/builder/users/*                    stores user SSH keys (used by builder)
 /deis/domains/*                          domain configuration for applications (used by router)
+/deis/logs/host                          IP address of the host running logger
 =============================            =================================================================================
 
 Settings used by controller

docs/customizing_deis/logger_settings.rst

@@ -28,7 +28,18 @@ setting                                  description
 
 Settings used by logger
 -------------------------
-The logger component uses no keys from etcd.
+The following etcd keys are used by the logger component.
+
+====================================      ================================================================================
+setting                                   description
+====================================      ================================================================================
+/deis/logs/storageAdapterType             Type of storage adapter to use: ``file`` or ``memory``; if not set, ``file`` is assumed.  It is also possible so specify the size of the in-memory adapter's internal ring buffer (in lines; a line is a max of 65k) using a value like: ``memory:<size>``.  1000 is the default size.
+/deis/logs/drain                          URL for an external service that logs can be forwarded to for long-term archival. If not set, no drain is used.  URLs beginning with ``udp://``, ``syslog://`` use UDP for transport.  URLs beginning with ``tcp://`` use TCP.
+====================================      ================================================================================
+
+.. note::
+
+  Those running the stateless (Ceph-less) platform should prefer the in-memory storage adapter.
 
 Using a custom logger image
 ---------------------------