Issue/logrotation

CHANGELOG.md

@@ -3,9 +3,10 @@ Changes in this release:
 - Various bugfixes and performance enhancements
 - Dependency updates
 - Removal of snapshot and restore functionality from the server (#789)
-- Replace virtualenv by python standard venv
+- Replace virtualenv by python standard venv (#783)
 - Updated to Tornado 5, moving from tornado ioloop to the standard python async framework (#765)
 - Extend mypy type annotations
+- Use files for all logs and split out logs, stdout and stderr in autostarted agents (#824, #234)
 
 v 2018.3 (2018-12-07)
 Changes in this release:

misc/inmanta-agent.service

@@ -4,7 +4,7 @@ After=network.target
 
 [Service]
 Type=simple
-ExecStart=/usr/bin/inmanta -c /etc/inmanta/agent.cfg -vv agent
+ExecStart=/usr/bin/inmanta -c /etc/inmanta/agent.cfg --log-file /var/log/inmanta/agent.log --timed-logs -vv agent
 Restart=on-failure
 User=root
 Group=root

misc/inmanta-server.service

@@ -6,7 +6,7 @@ After=network.target
 Type=simple
 User=inmanta
 Group=inmanta
-ExecStart=/usr/bin/inmanta -c /etc/inmanta/server.cfg -vv server
+ExecStart=/usr/bin/inmanta -c /etc/inmanta/server.cfg --log-file /var/log/inmanta/server.log --timed-logs -vv server
 Restart=on-failure
 
 [Install]

misc/logrotation_config

@@ -0,0 +1,7 @@
+/var/log/inmanta/*.log /var/log/inmanta/*.out /var/log/inmanta/*.err {
+	daily
+	compress
+	rotate 10
+	missingok
+	create 0644 inmanta inmanta
+}

src/inmanta/app.py

@@ -337,83 +337,83 @@ def cmd_parser():
     return parser
 
 
-def app():
-    """
-        Run the compiler
-    """
+def _get_default_stream_handler():
+    stream_handler = logging.StreamHandler(stream=sys.stdout)
+    stream_handler.setLevel(logging.INFO)
+
+    formatter = _get_log_formatter_for_stream_handler(timed=False)
+    stream_handler.setFormatter(formatter)
+
+    return stream_handler
+
+
+def _get_watched_file_handler(options):
+    if not options.log_file:
+        raise Exception("No logfile was provided.")
+    level = _convert_to_log_level(options.log_file_level)
+    formatter = logging.Formatter(fmt="%(asctime)s %(levelname)-8s %(name)-10s %(message)s")
+    file_handler = logging.handlers.WatchedFileHandler(filename=options.log_file, mode='a+')
+    file_handler.setFormatter(formatter)
+    file_handler.setLevel(level)
 
-    normalformatter = logging.Formatter(fmt="%(levelname)-8s%(message)s")
-    # set logging to sensible defaults
-    formatter = colorlog.ColoredFormatter(
-        "%(log_color)s%(levelname)-8s%(reset)s %(blue)s%(message)s",
-        datefmt=None,
-        reset=True,
-        log_colors={
-            'DEBUG': 'cyan',
-            'INFO': 'green',
-            'WARNING': 'yellow',
-            'ERROR': 'red',
-            'CRITICAL': 'red',
-        }
-    )
-
-    stream = logging.StreamHandler()
-    stream.setLevel(logging.INFO)
+    return file_handler
 
+
+def _convert_to_log_level(level):
+    if level >= len(log_levels):
+        level = 3
+    return log_levels[level]
+
+
+def _get_log_formatter_for_stream_handler(timed):
+    log_format = "%(asctime)s " if timed else ""
     if hasattr(sys.stdout, 'isatty') and sys.stdout.isatty():
-        stream.setFormatter(formatter)
+        log_format += "%(log_color)s%(levelname)-8s%(reset)s %(blue)s%(message)s"
+        formatter = colorlog.ColoredFormatter(
+            log_format,
+            datefmt=None,
+            reset=True,
+            log_colors={
+                'DEBUG': 'cyan',
+                'INFO': 'green',
+                'WARNING': 'yellow',
+                'ERROR': 'red',
+                'CRITICAL': 'red',
+            }
+        )
     else:
-        stream.setFormatter(normalformatter)
+        log_format += "%(levelname)-8s%(message)s"
+        formatter = logging.Formatter(fmt=log_format)
+    return formatter
+
 
+def app():
+    """
+        Run the compiler
+    """
+    # Send logs to stdout
+    stream_handler = _get_default_stream_handler()
     logging.root.handlers = []
-    logging.root.addHandler(stream)
+    logging.root.addHandler(stream_handler)
     logging.root.setLevel(0)
 
     # do an initial load of known config files to build the libdir path
     Config.load_config()
-
     parser = cmd_parser()
-
     options, other = parser.parse_known_args()
     options.other = other
 
-    if options.timed:
-        if hasattr(sys.stdout, 'isatty') and sys.stdout.isatty():
-            formatter = colorlog.ColoredFormatter(
-                "%(asctime)s %(log_color)s%(levelname)-8s%(reset)s %(blue)s%(message)s",
-                datefmt=None,
-                reset=True,
-                log_colors={
-                    'DEBUG': 'cyan',
-                    'INFO': 'green',
-                    'WARNING': 'yellow',
-                    'ERROR': 'red',
-                    'CRITICAL': 'red',
-                }
-            )
-        else:
-            formatter = logging.Formatter(fmt="%(asctime)s %(levelname)-8s%(message)s")
-        stream.setFormatter(formatter)
-
-    # set the log level
-    level = options.verbose
-    if level >= len(log_levels):
-        level = 3
-    stream.setLevel(log_levels[level])
-
-    # set the logfile
+    # Log everything to a log_file if logfile is provided
     if options.log_file:
-        level = options.log_file_level
-        if level >= len(log_levels):
-            level = 3
-
-        formatter = logging.Formatter(fmt="%(asctime)s %(levelname)-8s %(name)-10s %(message)s")
-
-        file_handler = logging.FileHandler(filename=options.log_file, mode="w")
-        file_handler.setFormatter(formatter)
-
-        file_handler.setLevel(log_levels[level])
-        logging.root.addHandler(file_handler)
+        watched_file_handler = _get_watched_file_handler(options)
+        logging.root.addHandler(watched_file_handler)
+        logging.root.removeHandler(stream_handler)
+    else:
+        if options.timed:
+            formatter = _get_log_formatter_for_stream_handler(timed=True)
+            stream_handler.setFormatter(formatter)
+        log_level = _convert_to_log_level(options.verbose)
+        stream_handler.setLevel(log_level)
 
     # Load the configuration
     Config.load_config(options.config_file)

src/inmanta/server/agentmanager.py

@@ -329,8 +329,7 @@ def _fork_inmanta(self, args, outfile, errfile, cwd=None):
                 errhandle = open(errfile, "wb+")
 
             # TODO: perhaps show in dashboard?
-            return subprocess.Popen(inmanta_path + args, cwd=cwd, env=os.environ.copy(),
-                                    stdout=outhandle, stderr=errhandle)
+            return subprocess.Popen(inmanta_path + args, cwd=cwd, env=os.environ.copy(), stdout=outhandle, stderr=errhandle)
         finally:
             if outhandle is not None:
                 outhandle.close()
@@ -463,13 +462,15 @@ def __do_start_agent(self, agents, env):
             fd.write(config)
 
         if not self._server._agent_no_log:
-            out = os.path.join(self._server_storage["logs"], "agent-%s.log" % env.id)
+            out = os.path.join(self._server_storage["logs"], "agent-%s.out" % env.id)
             err = os.path.join(self._server_storage["logs"], "agent-%s.err" % env.id)
         else:
             out = None
             err = None
 
-        proc = self._fork_inmanta(["-vvvv", "--timed-logs", "--config", config_path, "agent"], out, err)
+        agent_log = os.path.join(self._server_storage["logs"], "agent-%s.log" % env.id)
+        proc = self._fork_inmanta(["-vvvv", "--timed-logs", "--config", config_path, "--log-file", agent_log, "agent"],
+                                  out, err)
 
         if env.id in self._agent_procs and self._agent_procs[env.id] is not None:
             LOGGER.debug("Terminating old agent with PID %s", self._agent_procs[env.id].pid)

tests/test_app.py

@@ -0,0 +1,160 @@
+"""
+    Copyright 2018 Inmanta
+
+    Licensed under the Apache License, Version 2.0 (the "License");
+    you may not use this file except in compliance with the License.
+    You may obtain a copy of the License at
+
+        http://www.apache.org/licenses/LICENSE-2.0
+
+    Unless required by applicable law or agreed to in writing, software
+    distributed under the License is distributed on an "AS IS" BASIS,
+    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+    See the License for the specific language governing permissions and
+    limitations under the License.
+
+    Contact: code@inmanta.com
+"""
+
+import sys
+import os
+import subprocess
+import time
+import pytest
+import re
+import pty
+
+
+def get_command(tmp_dir, stdout_log_level=None, log_file=None, log_level_log_file=None, timed=False):
+    root_dir = tmp_dir.mkdir("root").strpath
+    log_dir = os.path.join(root_dir, "log")
+    state_dir = os.path.join(root_dir, "data")
+    for directory in [log_dir, state_dir]:
+        os.mkdir(directory)
+    config_file = os.path.join(root_dir, "inmanta.cfg")
+    with open(config_file, 'w+') as f:
+        f.write("[config]\n")
+        f.write("log-dir=" + log_dir + "\n")
+        f.write("state-dir=" + state_dir + "\n")
+    args = [sys.executable, "-m", "inmanta.app"]
+    if stdout_log_level:
+        args.append("-" + "v" * stdout_log_level)
+    if log_file:
+        log_file = os.path.join(log_dir, log_file)
+        args += ["--log-file", log_file]
+    if log_file and log_level_log_file:
+        args += ["--log-file-level", str(log_level_log_file)]
+    if timed:
+        args += ["--timed-logs"]
+    args += ["-c", config_file, "server"]
+    return (args, log_dir)
+
+
+def run_without_tty(args):
+    process = subprocess.Popen(args, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+    time.sleep(2)
+    process.kill()
+
+    def convert_to_ascii(lines):
+        return [line.decode('ascii') for line in lines if line != ""]
+
+    stdout = convert_to_ascii(process.stdout.readlines())
+    stderr = convert_to_ascii(process.stderr.readlines())
+    return (stdout, stderr)
+
+
+def run_with_tty(args):
+
+    def read(fd):
+        result = ""
+        while True:
+            try:
+                data = os.read(fd, 1024)
+            except OSError:
+                break
+            if data == "":
+                break
+            result += data.decode('ascii')
+        return result
+
+    master, slave = pty.openpty()
+    process = subprocess.Popen(' '.join(args), stdin=slave, stdout=slave, stderr=slave, shell=True)
+    os.close(slave)
+    time.sleep(2)  # Wait for some log lines
+    process.kill()
+    stdout = read(master)
+    stdout = stdout.split('\n')
+    os.close(master)
+    return (stdout, '')
+
+
+def get_timestamp_regex():
+    return r'[\d]{4}\-[\d]{2}\-[\d]{2} [\d]{2}\:[\d]{2}\:[\d]{2}\,[\d]{3}'
+
+
+@pytest.mark.parametrize("log_level, timed, with_tty, allowed_log_line_prefixes, invalid_log_line_prefixes", [
+    (3, False, False, ["ERROR ", "WARNING ", "INFO ", "DEBUG "], []),
+    (2, False, False, ["ERROR ", "WARNING ", "INFO "], ["DEBUG"]),
+    (3, True, False, ["ERROR ", "WARNING ", "INFO ", "DEBUG "], []),
+    (2, True, False, ["ERROR ", "WARNING ", "INFO "], ["DEBUG"]),
+    (3, False, True, [r'\x1b\[31mERROR ', r'\x1b\[33mWARNING ', r'\x1b\[32mINFO ', r'\x1b\[36mDEBUG '], []),
+    (2, False, True, [r'\x1b\[31mERROR ', r'\x1b\[33mWARNING ', r'\x1b\[32mINFO '], [r'\x1b\[36mDEBUG ']),
+    (3, True, True, [r'\x1b\[31mERROR ', r'\x1b\[33mWARNING ', r'\x1b\[32mINFO ', r'\x1b\[36mDEBUG '], []),
+    (2, True, True, [r'\x1b\[31mERROR ', r'\x1b\[33mWARNING ', r'\x1b\[32mINFO '], [r'\x1b\[36mDEBUG '])
+])
+def test_no_log_file_set(tmpdir, log_level, timed, with_tty, allowed_log_line_prefixes, invalid_log_line_prefixes):
+    (args, log_dir) = get_command(tmpdir, stdout_log_level=log_level, timed=timed)
+    if with_tty:
+        (stdout, stderr) = run_with_tty(args)
+    else:
+        (stdout, stderr) = run_without_tty(args)
+    assert os.listdir(log_dir) == []
+    assert len(stdout) != 0
+    assert len(stderr) == 0
+
+    def get_compiled_regex(prefixes):
+        regex = '(' + '|'.join(prefixes) + ')'
+        if timed:
+            regex = get_timestamp_regex() + ' ' + regex
+        return re.compile(regex)
+
+    reg_allowed = get_compiled_regex(allowed_log_line_prefixes)
+    if len(invalid_log_line_prefixes) > 0:
+        reg_invalid = get_compiled_regex(invalid_log_line_prefixes)
+    for line in stdout:
+        if len(line) > 0:
+            assert reg_allowed.match(line) is not None
+            if len(invalid_log_line_prefixes) > 0:
+                assert reg_invalid.match(line) is None
+
+
+@pytest.mark.parametrize("log_level, with_tty, allowed_log_line_prefixes, invalid_log_line_prefixes", [
+    (3, False, ["ERROR ", "WARNING ", "INFO ", "DEBUG "], []),
+    (2, False, ["ERROR ", "WARNING ", "INFO "], ["DEBUG"]),
+    (3, True, ["ERROR ", "WARNING ", "INFO ", "DEBUG "], []),
+    (2, True, ["ERROR ", "WARNING ", "INFO "], ["DEBUG"])
+])
+def test_log_file_set(tmpdir, log_level, with_tty, allowed_log_line_prefixes, invalid_log_line_prefixes):
+    log_file = "server.log"
+    (args, log_dir) = get_command(tmpdir, stdout_log_level=log_level, log_file=log_file, log_level_log_file=log_level)
+    if with_tty:
+        (stdout, stderr) = run_without_tty(args)
+    else:
+        (stdout, stderr) = run_without_tty(args)
+    assert os.listdir(log_dir) == [log_file]
+    assert len(stdout) == 0
+    assert len(stderr) == 0
+    log_file = os.path.join(log_dir, log_file)
+
+    def get_compiled_regex(prefixes):
+        regex_valid_prefixes = get_timestamp_regex() + ' (' + '|'.join(prefixes) + ')'
+        return re.compile(regex_valid_prefixes)
+
+    reg_allowed = get_compiled_regex(allowed_log_line_prefixes)
+    if len(invalid_log_line_prefixes) > 0:
+        reg_invalid = get_compiled_regex(invalid_log_line_prefixes)
+    with open(log_file, 'r') as f:
+        for line in f:
+            assert reg_allowed.match(line) is not None
+            if len(invalid_log_line_prefixes) > 0:
+                assert reg_invalid.match(line) is None