From 5c90ccfd74d28d817fab50079f0233cd8a555d3a Mon Sep 17 00:00:00 2001 From: Sam Thursfield Date: Fri, 29 Aug 2014 23:18:44 +0100 Subject: Clarify that multiple images can be deployed at once by `morph deploy` --- morphlib/plugins/deploy_plugin.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/morphlib/plugins/deploy_plugin.py b/morphlib/plugins/deploy_plugin.py index 61b8145e..b55478ad 100644 --- a/morphlib/plugins/deploy_plugin.py +++ b/morphlib/plugins/deploy_plugin.py @@ -43,7 +43,7 @@ class DeployPlugin(cliapp.Plugin): pass def deploy(self, args): - '''Deploy a built system image. + '''Deploy a built system image or a set of images. Command line arguments: -- cgit v1.2.1 From 864dff6aa72615a85e3c7180cfd65cacb66867da Mon Sep 17 00:00:00 2001 From: Sam Thursfield Date: Fri, 29 Aug 2014 23:18:45 +0100 Subject: Add `morph upgrade` command, deprecate `morph deploy --upgrade` The arguments to `morph deploy` can get quite long, any way we can make it shorter and clearer is useful. We can also avoid having the strange --no-upgrade flag in future. --- morphlib/exts/rawdisk.check | 4 ++-- morphlib/plugins/deploy_plugin.py | 30 ++++++++++++++++++++++++++---- yarns/deployment.yarn | 2 +- yarns/implementations.yarn | 2 +- 4 files changed, 30 insertions(+), 8 deletions(-) diff --git a/morphlib/exts/rawdisk.check b/morphlib/exts/rawdisk.check index 5e75abe2..acdc4de1 100755 --- a/morphlib/exts/rawdisk.check +++ b/morphlib/exts/rawdisk.check @@ -46,7 +46,7 @@ class RawdiskCheckExtension(morphlib.writeexts.WriteExtension): else: if os.path.exists(location): raise cliapp.AppException( - 'Target %s already exists. Pass --upgrade if you want to ' - 'update an existing image.' % location) + 'Target %s already exists. Use `morph upgrade` if you ' + 'want to update an existing image.' % location) RawdiskCheckExtension().run() diff --git a/morphlib/plugins/deploy_plugin.py b/morphlib/plugins/deploy_plugin.py index b55478ad..f3e43fa8 100644 --- a/morphlib/plugins/deploy_plugin.py +++ b/morphlib/plugins/deploy_plugin.py @@ -32,12 +32,15 @@ class DeployPlugin(cliapp.Plugin): group_deploy = 'Deploy Options' self.app.settings.boolean(['upgrade'], 'specify that you want to upgrade an ' - 'existing cluster of systems rather than do ' - 'an initial deployment', + 'existing cluster. Deprecated: use the ' + '`morph upgrade` command instead', group=group_deploy) self.app.add_subcommand( 'deploy', self.deploy, arg_synopsis='CLUSTER [DEPLOYMENT...] [SYSTEM.KEY=VALUE]') + self.app.add_subcommand( + 'upgrade', self.upgrade, + arg_synopsis='CLUSTER [DEPLOYMENT...] [SYSTEM.KEY=VALUE]') def disable(self): pass @@ -300,8 +303,8 @@ class DeployPlugin(cliapp.Plugin): if cluster_morphology['kind'] != 'cluster': raise cliapp.AppException( - "Error: morph deploy is only supported for cluster" - " morphologies.") + "Error: morph deployment commands are only supported for " + "cluster morphologies.") # parse the rest of the args all_subsystems = set() @@ -432,6 +435,25 @@ class DeployPlugin(cliapp.Plugin): finally: self.app.status_prefix = old_status_prefix + def upgrade(self, args): + '''Upgrade an existing set of instances using built images. + + See `morph help deploy` for documentation. + + ''' + + if not args: + raise cliapp.AppException( + 'Too few arguments to upgrade command (see `morph help ' + 'deploy`)') + + if self.app.settings['upgrade']: + raise cliapp.AppException( + 'Running `morph upgrade --upgrade` does not make sense.') + + self.app.settings['upgrade'] = True + self.deploy(args) + def check_deploy(self, root_repo_dir, ref, deployment_type, location, env): # Run optional write check extension. These are separate from the write # extension because it may be several minutes before the write diff --git a/yarns/deployment.yarn b/yarns/deployment.yarn index 4039d551..40b50432 100644 --- a/yarns/deployment.yarn +++ b/yarns/deployment.yarn @@ -7,7 +7,7 @@ Morph Deployment Tests WHEN the user checks out the system branch called master AND the user attempts to deploy the system systems/test-system.morph in branch master THEN morph failed - AND the deploy error message includes the string "morph deploy is only supported for cluster morphologies" + AND the deploy error message includes the string "morph deployment commands are only supported for cluster morphologies" FINALLY the git server is shut down SCENARIO deploying a cluster morphology as a tarfile diff --git a/yarns/implementations.yarn b/yarns/implementations.yarn index 422c2eea..52eee01d 100644 --- a/yarns/implementations.yarn +++ b/yarns/implementations.yarn @@ -692,7 +692,7 @@ them, so they can be added to the end of the implements section. IMPLEMENTS WHEN the user (attempts to upgrade|upgrades) the (system|cluster) (\S+) in branch (\S+)( with options (.*))? cd "$DATADIR/workspace/$MATCH_4" - set -- deploy --upgrade "$MATCH_3" + set -- upgrade "$MATCH_3" if [ "$MATCH_5" != '' ]; then # eval used so word splitting in the text is preserved eval set -- '"$@"' $MATCH_6 -- cgit v1.2.1 From 6fba43005c52930ce0175df18122264c2f193448 Mon Sep 17 00:00:00 2001 From: Richard Maw Date: Fri, 29 Aug 2014 23:18:46 +0100 Subject: deploy: Allow extensions to write to Morph log file This is achieved by passing it the write end of a pipe, so that the extension has somewhere to write debug messages without clobbering either stdout or stderr. Previously deployment extensions could only display status messages on stdout, which is good for telling the user what is happening but is not useful when trying to do post-mortem debugging, when more information is usually required. This uses the asyncore asynchronous event framework, which is rather specific to sockets, but can be made to work with file descriptors, and has the advantage that it's part of the python standard library. It relies on polling file descriptors, but there's a trick with pipes to use them as a notification that a process has exited: 1. Ensure the write-end of the pipe is only open in the process you want to know when it exits 2. Make sure the pipe's FDs are set in non-blocking read/write mode 3. Call select or poll on the read-end of the file descriptor 4. If select/poll says you can read from that FD, but you get an EOF, then the process has closed it, and if you know it doesn't do that in normal operation, then the process has terminated. It took a few weird hacks to get the async_chat module to unregister its event handlers on EOF, but the result is an event loop that is asleep until the kernel tells it that it has to do something. --- morphlib/extensions.py | 116 +++++++++++++++++++++++++++++++++++++- morphlib/plugins/deploy_plugin.py | 53 +++++++++-------- 2 files changed, 143 insertions(+), 26 deletions(-) diff --git a/morphlib/extensions.py b/morphlib/extensions.py index 55478418..af6ba279 100644 --- a/morphlib/extensions.py +++ b/morphlib/extensions.py @@ -13,14 +13,21 @@ # with this program; if not, write to the Free Software Foundation, Inc., # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. -import cliapp -import morphlib +import asyncore +import asynchat import glob +import logging import os -import sysbranchdir import stat +import subprocess import tempfile +import cliapp + +import morphlib +import sysbranchdir + + class ExtensionError(morphlib.Error): pass @@ -149,3 +156,106 @@ class get_extension_filename(): def __exit__(self, type, value, trace): if self.delete: os.remove(self.ext_filename) + + +class _EOFWrapper(asyncore.file_wrapper): + '''File object that reports when it hits EOF + + The async_chat class doesn't notice that its input file has hit EOF, + so if we give it one of these instead, it will mark the chatter for + closiure and ensure any in-progress buffers are flushed. + ''' + def __init__(self, dispatcher, fd): + self._dispatcher = dispatcher + asyncore.file_wrapper.__init__(self, fd) + + def recv(self, *args): + data = asyncore.file_wrapper.recv(self, *args) + if not data: + self._dispatcher.close_when_done() + # ensure any unterminated data is flushed + return self._dispatcher.get_terminator() + return data + + +class _OutputDispatcher(asynchat.async_chat, asyncore.file_dispatcher): + '''asyncore dispatcher that calls line_handler per line.''' + def __init__(self, fd, line_handler, map=None): + asynchat.async_chat.__init__(self, sock=None, map=map) + asyncore.file_dispatcher.__init__(self, fd=fd, map=map) + self.set_terminator('\n') + self._line_handler = line_handler + collect_incoming_data = asynchat.async_chat._collect_incoming_data + def set_file(self, fd): + self.socket = _EOFWrapper(self, fd) + self._fileno = self.socket.fileno() + self.add_channel() + def found_terminator(self): + self._line_handler(''.join(self.incoming)) + self.incoming = [] + +class ExtensionSubprocess(object): + + def __init__(self, report_stdout, report_stderr, report_logger): + self._report_stdout = report_stdout + self._report_stderr = report_stderr + self._report_logger = report_logger + + def run(self, filename, args, cwd, env): + '''Run an extension. + + Anything written by the extension to stdout is passed to status(), thus + normally echoed to Morph's stdout. An extra FD is passed in the + environment variable MORPH_LOG_FD, and anything written here will be + included as debug messages in Morph's log file. + + ''' + + log_read_fd, log_write_fd = os.pipe() + + try: + new_env = env.copy() + new_env['MORPH_LOG_FD'] = str(log_write_fd) + + # Because we don't have python 3.2's pass_fds, we have to + # play games with preexec_fn to close the fds we don't + # need to inherit + def close_read_end(): + os.close(log_read_fd) + p = subprocess.Popen( + [filename] + args, cwd=cwd, env=new_env, + stdout=subprocess.PIPE, stderr=subprocess.PIPE, + preexec_fn=close_read_end) + os.close(log_write_fd) + log_write_fd = None + + return self._watch_extension_subprocess(p, log_read_fd) + finally: + os.close(log_read_fd) + if log_write_fd is not None: + os.close(log_write_fd) + + def _watch_extension_subprocess(self, p, log_read_fd): + '''Follow stdout, stderr and log output of an extension subprocess.''' + + try: + socket_map = {} + for handler, fd in ((self._report_stdout, p.stdout), + (self._report_stderr, p.stderr), + (self._report_logger, log_read_fd)): + _OutputDispatcher(line_handler=handler, fd=fd, + map=socket_map) + asyncore.loop(use_poll=True, map=socket_map) + + returncode = p.wait() + assert returncode is not None + except BaseException as e: + logging.debug('Received exception %r watching extension' % e) + p.terminate() + p.wait() + raise + finally: + p.stdout.close() + p.stderr.close() + + return returncode diff --git a/morphlib/plugins/deploy_plugin.py b/morphlib/plugins/deploy_plugin.py index f3e43fa8..a80079fa 100644 --- a/morphlib/plugins/deploy_plugin.py +++ b/morphlib/plugins/deploy_plugin.py @@ -14,18 +14,19 @@ # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. -import cliapp -import contextlib import json +import logging import os import shutil -import stat +import sys import tarfile import tempfile import uuid +import cliapp import morphlib + class DeployPlugin(cliapp.Plugin): def enable(self): @@ -540,33 +541,39 @@ class DeployPlugin(cliapp.Plugin): self.app.status(msg='Cleaning up') shutil.rmtree(deploy_private_tempdir) + def _report_extension_stdout(self, line): + self.app.status(msg=line.replace('%s', '%%')) + def _report_extension_stderr(self, error_list): + def cb(line): + error_list.append(line) + sys.stderr.write('%s\n' % line) + return cb + def _report_extension_logger(self, name, kind): + return lambda line: logging.debug('%s%s: %s', name, kind, line) def _run_extension(self, gd, name, kind, args, env): '''Run an extension. - + The ``kind`` should be either ``.configure`` or ``.write``, depending on the kind of extension that is sought. - + The extension is found either in the git repository of the system morphology (repo, ref), or with the Morph code. - + ''' - with morphlib.extensions.get_extension_filename( - name, kind) as ext_filename: - self.app.status(msg='Running extension %(name)s%(kind)s', - name=name, kind=kind) - self.app.runcmd( - [ext_filename] + args, - ['sh', - '-c', - 'while read l; do echo `date "+%F %T"` "$1$l"; done', - '-', - '%s[%s]' % (self.app.status_prefix, name + kind)], - cwd=gd.dirname, env=env, stdout=None, stderr=None) - - def _is_executable(self, filename): - st = os.stat(filename) - mask = stat.S_IXUSR | stat.S_IXGRP | stat.S_IXOTH - return (stat.S_IMODE(st.st_mode) & mask) != 0 + error_list = [] + with morphlib.extensions.get_extension_filename(name, kind) as fn: + ext = morphlib.extensions.ExtensionSubprocess( + report_stdout=self._report_extension_stdout, + report_stderr=self._report_extension_stderr(error_list), + report_logger=self._report_extension_logger(name, kind), + ) + returncode = ext.run(fn, args, env=env, cwd=gd.dirname) + if returncode == 0: + logging.info('%s%s succeeded', name, kind) + else: + message = '%s%s failed with code %s: %s' % ( + name, kind, returncode, '\n'.join(error_list)) + raise cliapp.AppException(message) def create_metadata(self, system_artifact, root_repo_dir, deployment_type, location, env): -- cgit v1.2.1 From 354253df295bb2815a9d5e0744b3aa98eea6aad9 Mon Sep 17 00:00:00 2001 From: Sam Thursfield Date: Fri, 29 Aug 2014 23:18:47 +0100 Subject: deploy: Make Python extensions log debug messages to MORPH_LOG_FD by default Previously logging was disabled for Python deploy extensions. We get a lot of useful information for free in the log file by doing this: the environment will be written when the subprocess starts, and if it crashes the full backtrace will be written there too. Subcommand execution with cliapp.runcmd() will also be logged. --- morphlib/writeexts.py | 25 ++++++++++++++++++++++++- 1 file changed, 24 insertions(+), 1 deletion(-) diff --git a/morphlib/writeexts.py b/morphlib/writeexts.py index c3605b1c..5102bfdc 100644 --- a/morphlib/writeexts.py +++ b/morphlib/writeexts.py @@ -89,7 +89,30 @@ class WriteExtension(cliapp.Application): write extensions. ''' - + + def setup_logging(self): + '''Direct all logging output to MORPH_LOG_FD, if set. + + This file descriptor is read by Morph and written into its own log + file. + + This overrides cliapp's usual configurable logging setup. + + ''' + log_write_fd = int(os.environ.get('MORPH_LOG_FD', 0)) + + if log_write_fd == 0: + return + + formatter = logging.Formatter('%(message)s') + + handler = logging.StreamHandler(os.fdopen(log_write_fd, 'w')) + handler.setFormatter(formatter) + + logger = logging.getLogger() + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + def process_args(self, args): raise NotImplementedError() -- cgit v1.2.1