Improve handling of Puppet output

Currently the output of Puppet run is written to os-collect-config log only.
If the run gets stuck, we have zero output from it, and have no chance
of guessing where it got stuck. This patch is fixing this issue and also adds
support for running Puppet in debug mode.

Due to big amount of data stdout and stderr in response during debug mode,
both are trimmed so that we won't exceed  max_json_body_size(1048576).

Resolves-bug: rhbz#1242396

Change-Id: Ie92d1714a8d7e59d347474039be999bd3a2b542f
This commit is contained in:
Martin Mágr 2015-06-05 12:44:29 +02:00 committed by Kanagaraj Manickam
parent f9936ee29a
commit 2636f415b8
3 changed files with 93 additions and 15 deletions

View File

@ -15,14 +15,19 @@
import json
import logging
import os
import re
import subprocess
import sys
WORKING_DIR = os.environ.get('HEAT_PUPPET_WORKING',
'/var/lib/heat-config/heat-config-puppet')
OUTPUTS_DIR = os.environ.get('HEAT_PUPPET_OUTPUTS',
'/var/run/heat-config/heat-config-puppet')
PUPPET_CMD = os.environ.get('HEAT_PUPPET_CMD', 'puppet')
PUPPET_LOGDIR = os.environ.get(
'HEAT_PUPPET_LOGDIR', '/var/run/heat-config/deployed'
)
HIERA_DATADIR = os.environ.get('HEAT_PUPPET_HIERA_DATADIR',
'/etc/puppet/hieradata')
@ -61,6 +66,7 @@ def main(argv=sys.argv):
use_facter = c['options'].get('enable_facter', True)
modulepath = c['options'].get('modulepath')
tags = c['options'].get('tags')
debug = c['options'].get('enable_debug', False)
facts = {}
hiera = {}
@ -100,6 +106,7 @@ def main(argv=sys.argv):
with os.fdopen(os.open(fn, os.O_CREAT | os.O_TRUNC | os.O_WRONLY, 0o700),
'w') as f:
f.write(c.get('config', '').encode('utf-8'))
cmd = [PUPPET_CMD, 'apply', '--detailed-exitcodes', fn]
if modulepath:
cmd.insert(-1, '--modulepath')
@ -107,20 +114,37 @@ def main(argv=sys.argv):
if tags:
cmd.insert(-1, '--tags')
cmd.insert(-1, tags)
if debug:
cmd.insert(-1, '--debug')
prepare_dir(PUPPET_LOGDIR)
timestamp = re.sub('[:T]', '-', c['creation_time'])
base_path = os.path.join(
PUPPET_LOGDIR, '{timestamp}-{c[id]}'.format(**locals())
)
stdout_log = open('{0}-stdout.log'.format(base_path), 'w')
stderr_log = open('{0}-stderr.log'.format(base_path), 'w')
log.debug('Running %s %s' % (env_debug, ' '.join(cmd)))
try:
subproc = subprocess.Popen(cmd, stdout=subprocess.PIPE,
stderr=subprocess.PIPE, env=env)
subproc = subprocess.Popen(
cmd, stdout=stdout_log, stderr=stderr_log, env=env
)
subproc.wait()
except OSError:
log.warn('puppet not installed yet')
return
stdout, stderr = subproc.communicate()
finally:
stdout_log.close()
stderr_log.close()
log.info('Return code %s' % subproc.returncode)
if stdout:
log.info(stdout)
if stderr:
log.info(stderr)
response = {}
for i in 'stdout', 'stderr':
with open('{0}-{1}.log'.format(base_path, i)) as logfile:
content = logfile.read()
if content.strip():
log.info(content)
response['deploy_{0}'.format(i)] = content
# returncode of 2 means there were successfull changes
if subproc.returncode in (0, 2):
@ -130,8 +154,6 @@ def main(argv=sys.argv):
returncode = subproc.returncode
log.error("Error running %s. [%s]\n" % (fn, subproc.returncode))
response = {}
for output in c.get('outputs') or []:
output_name = output['name']
try:
@ -141,12 +163,10 @@ def main(argv=sys.argv):
pass
response.update({
'deploy_stdout': stdout,
'deploy_stderr': stderr,
'deploy_status_code': returncode,
})
json.dump(response, sys.stdout)
if __name__ == '__main__':
sys.exit(main(sys.argv))

View File

@ -35,6 +35,9 @@ except ImportError:
zaqarclient = None
MAX_RESPONSE_SIZE = 950000
def init_logging():
log = logging.getLogger('heat-config-notify')
handler = logging.StreamHandler(sys.stderr)
@ -46,6 +49,29 @@ def init_logging():
return log
def trim_response(response, trimmed_values=None):
"""Trim selected values from response.
Makes given response smaller or the same size as MAX_RESPONSE_SIZE by
trimming given trimmed_values from response dict from the left side
(beginning). Returns trimmed and serialized JSON response itself.
"""
trimmed_values = trimmed_values or ('deploy_stdout', 'deploy_stderr')
str_response = json.dumps(response, ensure_ascii=True, encoding='utf-8')
len_total = len(str_response)
offset = MAX_RESPONSE_SIZE - len_total
if offset >= 0:
return str_response
offset = abs(offset)
for key in trimmed_values:
len_value = len(response[key])
cut = int(round(float(len_value) / len_total * offset))
response[key] = response[key][cut:]
str_response = json.dumps(response, ensure_ascii=True, encoding='utf-8')
return str_response
def main(argv=sys.argv, stdin=sys.stdin):
log = init_logging()
@ -75,13 +101,15 @@ def main(argv=sys.argv, stdin=sys.stdin):
if 'deploy_signal_id' in iv:
sigurl = iv.get('deploy_signal_id')
sigverb = iv.get('deploy_signal_verb', 'POST')
signal_data = json.dumps(signal_data)
log.debug('Signaling to %s via %s' % (sigurl, sigverb))
# we need to trim log content because Heat response size is limited
# by max_json_body_size = 1048576
str_signal_data = trim_response(signal_data)
if sigverb == 'PUT':
r = requests.put(sigurl, data=signal_data,
r = requests.put(sigurl, data=str_signal_data,
headers={'content-type': None})
else:
r = requests.post(sigurl, data=signal_data,
r = requests.post(sigurl, data=str_signal_data,
headers={'content-type': None})
log.debug('Response %s ' % r)

View File

@ -24,11 +24,13 @@ class HookPuppetTest(common.RunScriptTest):
data = {
'id': '1234',
'creation_time': '2015-07-16T11:40:20',
'name': 'fake_resource_name',
'group': 'puppet',
'options': {
'enable_hiera': True,
'enable_facter': True,
'enable_debug': True,
},
'inputs': [
{'name': 'foo', 'value': 'bar'},
@ -55,6 +57,7 @@ class HookPuppetTest(common.RunScriptTest):
self.working_dir = self.useFixture(fixtures.TempDir())
self.outputs_dir = self.useFixture(fixtures.TempDir())
self.log_dir = self.useFixture(fixtures.TempDir())
self.hiera_datadir = self.useFixture(fixtures.TempDir())
self.test_state_path = self.outputs_dir.join('test_state.json')
@ -62,6 +65,7 @@ class HookPuppetTest(common.RunScriptTest):
self.env.update({
'HEAT_PUPPET_WORKING': self.working_dir.join(),
'HEAT_PUPPET_OUTPUTS': self.outputs_dir.join(),
'HEAT_PUPPET_LOGDIR': self.log_dir.join(),
'HEAT_PUPPET_HIERA_DATADIR': self.hiera_datadir.join(),
'HEAT_PUPPET_CMD': self.fake_tool_path,
'TEST_STATE_PATH': self.test_state_path,
@ -98,6 +102,7 @@ class HookPuppetTest(common.RunScriptTest):
self.fake_tool_path,
'apply',
'--detailed-exitcodes',
'--debug',
puppet_script
],
state['args'])
@ -109,6 +114,29 @@ class HookPuppetTest(common.RunScriptTest):
with open(puppet_script) as f:
self.assertEqual('the puppet script', f.read())
def test_hook_no_debug(self):
self.data['options']['enable_debug'] = False
self.env.update({
'TEST_RESPONSE': json.dumps({
'stdout': 'success',
'stderr': '',
}),
})
returncode, stdout, stderr = self.run_cmd(
[self.hook_path], self.env, json.dumps(self.data))
state = self.json_from_file(self.test_state_path)
puppet_script = self.working_dir.join('1234.pp')
self.assertEqual(
[
self.fake_tool_path,
'apply',
'--detailed-exitcodes',
puppet_script
],
state['args'])
self.data['options']['enable_debug'] = True
def test_hook_puppet_failed(self):
self.env.update({
@ -135,6 +163,7 @@ class HookPuppetTest(common.RunScriptTest):
self.fake_tool_path,
'apply',
'--detailed-exitcodes',
'--debug',
puppet_script
],
state['args'])
@ -187,6 +216,7 @@ class HookPuppetTest(common.RunScriptTest):
modulepath,
'--tags',
'package,file',
'--debug',
puppet_script
],
state['args'])