Commit c0b2e670 authored by Xavier Thompson's avatar Xavier Thompson

slapgrid: Fix promises not being logged to logfile

Promises processed using the instance's python in a subprocess were
logged to the console but not to the logfile passed by `--logfile`.

To fix this the output of the promise is now captured and forwarded
to slapgrid's logger in real-time using SlapPopen.
parent 6d936dcd
......@@ -60,11 +60,11 @@ promise_checker = PromiseLauncher(config=config, logger=app.log)
# Run promises
# Redirect stdout to stderr (logger only uses stderr already)
# to reserve stdout for error reporting
# Redirect stderr to stdout (logger uses stderr)
# to reserve stderr exclusively for error reporting
out = os.dup(1)
os.dup2(2, 1)
err = os.dup(2)
os.dup2(1, 2)
try:
promise_checker.run()
......@@ -73,5 +73,5 @@ except Exception as e:
error_str = unicode(str(e), 'utf-8', 'repr')
else:
error_str = str(e)
os.write(out, error_str.encode('utf-8', 'repr'))
os.write(err, error_str.encode('utf-8', 'repr'))
sys.exit(2 if isinstance(e, PromiseError) else 1)
......@@ -726,26 +726,30 @@ stderr_logfile_backups=1
else:
command.append('--' + option)
command.append(str(value))
process = subprocess.Popen(
command,
preexec_fn=lambda: dropPrivileges(uid, gid, logger=self.logger),
cwd=instance_path,
universal_newlines=True,
stdout=subprocess.PIPE)
promises = plugins + len(listifdir(legacy_promise_dir))
# Add a timeout margin to let the process kill the promises and cleanup
timeout = promises * self.promise_timeout + 10
# The runpromise script uses stderr exclusively to propagate exception
# messages. It otherwise redirects stderr to stdout so that all outputs
# from the promises go to stdout.
try:
# The logger logs everything to stderr, so runpromise redirects
# stdout to stderr in case a promise prints to stdout
# and reserves stdout to progagate exception messages.
out, _ = process.communicate(timeout=timeout)
process = SlapPopen(
command,
preexec_fn=lambda: dropPrivileges(uid, gid, logger=self.logger),
cwd=instance_path,
universal_newlines=True,
stdout=subprocess.PIPE,
stderr=subprocess.PIPE,
logger=self.logger,
timeout=timeout,
)
stderr = process.stderr.read()
if process.returncode == 2:
raise PromiseError(out)
raise PromiseError(stderr)
elif process.returncode:
raise Exception(out)
elif out:
self.logger.warn('Promise runner unexpected output:\n%s', out)
raise Exception(stderr)
elif stderr:
self.logger.warn('Promise runner unexpected output:\n%s', stderr)
except subprocess.TimeoutExpired:
killProcessTree(process.pid, self.logger)
# The timeout margin was exceeded but this should be infrequent
......
......@@ -34,13 +34,17 @@ import os
import pkg_resources
import pwd
import stat
import subprocess
import sys
import threading
import logging
import psutil
import time
if sys.version_info >= (3,):
import subprocess
else:
import subprocess32 as subprocess
from slapos.grid.exception import BuildoutFailedError, WrongPermissionError
......@@ -119,6 +123,7 @@ class SlapPopen(subprocess.Popen):
"""
def __init__(self, *args, **kwargs):
logger = kwargs.pop('logger')
timeout = kwargs.pop('timeout', None)
debug = kwargs.pop('debug', False)
if debug:
......@@ -154,7 +159,7 @@ class SlapPopen(subprocess.Popen):
args=(self.stdout, output_lines, logger))
t.start()
try:
self.wait()
self.wait(timeout=timeout)
finally:
t.join()
self.output = ''.join(output_lines)
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment