From be8827b67c88d1c2103e55ddf8a4021c09b4101a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Fri, 3 Jul 2015 13:59:22 +0200 Subject: [PATCH] SWU: plugin now logs stdout/stderr during updating Only if logged in as Admin though. Working dialog is as verbose as Plugin install dialog. --- .../plugins/softwareupdate/__init__.py | 34 ++++- .../static/css/softwareupdate.css | 2 +- .../static/js/softwareupdate.js | 127 +++++++++++++++--- .../static/less/softwareupdate.less | 32 ++++- .../templates/softwareupdate_settings.jinja2 | 13 ++ .../plugins/softwareupdate/updaters/pip.py | 39 +++--- .../softwareupdate/updaters/python_updater.py | 4 +- .../softwareupdate/updaters/update_script.py | 66 ++++----- 8 files changed, 239 insertions(+), 78 deletions(-) diff --git a/src/octoprint/plugins/softwareupdate/__init__.py b/src/octoprint/plugins/softwareupdate/__init__.py index 157f671b..c9734883 100644 --- a/src/octoprint/plugins/softwareupdate/__init__.py +++ b/src/octoprint/plugins/softwareupdate/__init__.py @@ -12,6 +12,8 @@ import flask import os import threading import time +import logging +import logging.handlers from . import version_checks, updaters, exceptions, util @@ -28,7 +30,8 @@ import octoprint.settings class SoftwareUpdatePlugin(octoprint.plugin.BlueprintPlugin, octoprint.plugin.SettingsPlugin, octoprint.plugin.AssetPlugin, - octoprint.plugin.TemplatePlugin): + octoprint.plugin.TemplatePlugin, + octoprint.plugin.StartupPlugin): def __init__(self): self._update_in_progress = False self._configured_checks_mutex = threading.Lock() @@ -40,7 +43,11 @@ class SoftwareUpdatePlugin(octoprint.plugin.BlueprintPlugin, self._version_cache_path = None self._version_cache_dirty = False + self._console_logger = None + def initialize(self): + self._console_logger = logging.getLogger("octoprint.plugins.softwareupdate.console") + self._version_cache_ttl = self._settings.get_int(["cache_ttl"]) * 60 self._version_cache_path = os.path.join(self.get_plugin_data_folder(), "versioncache.yaml") self._load_version_cache() @@ -52,6 +59,15 @@ class SoftwareUpdatePlugin(octoprint.plugin.BlueprintPlugin, self._plugin_lifecycle_manager.add_callback("enabled", refresh_checks) self._plugin_lifecycle_manager.add_callback("disabled", refresh_checks) + def on_startup(self, host, port): + console_logging_handler = logging.handlers.RotatingFileHandler(self._settings.get_plugin_logfile_path(postfix="console"), maxBytes=2*1024*1024) + console_logging_handler.setFormatter(logging.Formatter("%(asctime)s %(message)s")) + console_logging_handler.setLevel(logging.DEBUG) + + self._console_logger.addHandler(console_logging_handler) + self._console_logger.setLevel(logging.DEBUG) + self._console_logger.propagate = False + def _get_configured_checks(self): with self._configured_checks_mutex: if self._refresh_configured_checks or self._configured_checks is None: @@ -400,9 +416,6 @@ class SoftwareUpdatePlugin(octoprint.plugin.BlueprintPlugin, self._version_cache_dirty = True return information, update_available, update_possible - def _send_client_message(self, message_type, data=None): - self._plugin_manager.send_plugin_message("softwareupdate", dict(type=message_type, data=data)) - def perform_updates(self, check_targets=None, force=False): """ Performs the updates for the given check_targets. Will update all possible targets by default. @@ -518,7 +531,7 @@ class SoftwareUpdatePlugin(octoprint.plugin.BlueprintPlugin, if updater is None: raise exceptions.UnknownUpdateType() - update_result = updater.perform_update(target, check, target_version) + update_result = updater.perform_update(target, check, target_version, log_cb=self._log) target_result = ("success", update_result) self._logger.info("Update of %s to %s successful!" % (target, target_version)) @@ -573,6 +586,17 @@ class SoftwareUpdatePlugin(octoprint.plugin.BlueprintPlugin, self._logger.warn("Restart stderr:\n%s" % e.stderr) raise exceptions.RestartFailed() + def _log(self, lines, prefix=None, stream=None, strip=True): + if strip: + lines = map(lambda x: x.strip(), lines) + + self._send_client_message("loglines", data=dict(loglines=[dict(line=line, stream=stream) for line in lines])) + for line in lines: + self._console_logger.debug(u"{prefix} {line}".format(**locals())) + + def _send_client_message(self, message_type, data=None): + self._plugin_manager.send_plugin_message(self._identifier, dict(type=message_type, data=data)) + def _get_version_checker(self, target, check): """ Retrieves the version checker to use for given target and check configuration. Will raise an UnknownCheckType diff --git a/src/octoprint/plugins/softwareupdate/static/css/softwareupdate.css b/src/octoprint/plugins/softwareupdate/static/css/softwareupdate.css index 3fc6f48c..62e01e24 100644 --- a/src/octoprint/plugins/softwareupdate/static/css/softwareupdate.css +++ b/src/octoprint/plugins/softwareupdate/static/css/softwareupdate.css @@ -1 +1 @@ -td.settings_plugin_softwareupdate_column_update{width:16px} \ No newline at end of file +td.settings_plugin_softwareupdate_column_update{width:16px}#settings_plugin_softwareupdate_workingdialog_output{font-size:.8em}#settings_plugin_softwareupdate_workingdialog_output .message{font-weight:bold}#settings_plugin_softwareupdate_workingdialog_output .separator{font-weight:bold;color:#666}#settings_plugin_softwareupdate_workingdialog_output .stdout{color:#333}#settings_plugin_softwareupdate_workingdialog_output .stderr{color:#900}#settings_plugin_softwareupdate_workingdialog_output .call{color:#009}#settings_plugin_softwareupdate_workingdialog_output .message_error{font-weight:bold;color:#900} \ No newline at end of file diff --git a/src/octoprint/plugins/softwareupdate/static/js/softwareupdate.js b/src/octoprint/plugins/softwareupdate/static/js/softwareupdate.js index 1fea8360..b0c5726c 100644 --- a/src/octoprint/plugins/softwareupdate/static/js/softwareupdate.js +++ b/src/octoprint/plugins/softwareupdate/static/js/softwareupdate.js @@ -13,6 +13,12 @@ $(function() { self.currentlyBeingUpdated = []; + self.working = ko.observable(false); + self.workingTitle = ko.observable(); + self.workingDialog = undefined; + self.workingOutput = undefined; + self.loglines = ko.observableArray([]); + self.config_restartCommand = ko.observable(); self.config_rebootCommand = ko.observable(); self.config_cacheTtl = ko.observable(); @@ -259,6 +265,7 @@ $(function() { }, success: function(data) { self.currentlyBeingUpdated = data.checks; + self._markWorking(gettext("Updating..."), gettext("Updating, please wait.")); } }); }; @@ -276,18 +283,55 @@ $(function() { type: "error" }); } else { - $("#confirmation_dialog .confirmation_dialog_message").text(gettext("This will update your OctoPrint installation and restart the server.")); - $("#confirmation_dialog .confirmation_dialog_acknowledge").unbind("click"); - $("#confirmation_dialog .confirmation_dialog_acknowledge").click(function(e) { + showConfirmationDialog(gettext("This will update your OctoPrint installation and restart the server."), function(e) { e.preventDefault(); $("#confirmation_dialog").modal("hide"); self.performUpdate(force); }); - $("#confirmation_dialog").modal("show"); } }; + self._showWorkingDialog = function(title) { + if (!self.loginState.isAdmin()) { + return; + } + + self.working(true); + self.workingTitle(title); + self.workingDialog.modal("show"); + }; + + self._markWorking = function(title, line, stream) { + if (stream === undefined) { + stream = "message"; + } + + self.loglines.removeAll(); + self.loglines.push({line: line, stream: stream}); + self._showWorkingDialog(title); + }; + + self._markDone = function(line, stream) { + if (stream === undefined) { + stream = "message"; + } + + self.working(false); + self.loglines.push({line: "", stream: stream}); + self.loglines.push({line: line, stream: stream}); + self._scrollWorkingOutputToEnd(); + }; + + self._scrollWorkingOutputToEnd = function() { + self.workingOutput.scrollTop(self.workingOutput[0].scrollHeight - self.workingOutput.height()); + }; + + self.onStartup = function() { + self.workingDialog = $("#settings_plugin_softwareupdate_workingdialog"); + self.workingOutput = $("#settings_plugin_softwareupdate_workingdialog_output"); + }; + self.onServerDisconnect = function() { if (self.restartTimeout !== undefined) { clearTimeout(self.restartTimeout); @@ -323,15 +367,37 @@ $(function() { var options = undefined; + var restartType = undefined; + var title = undefined; + var text = undefined; + switch (messageType) { + case "loglines": { + if (self.working()) { + _.each(messageData.loglines, function(line) { + self.loglines.push(line); + }); + self._scrollWorkingOutputToEnd(); + } + break; + } case "updating": { console.log(JSON.stringify(messageData)); + if (!self.working()) { + self._markWorking(gettext("Updating..."), gettext("Updating, please wait.")); + } + var name = self.currentlyBeingUpdated[messageData.target]; if (name == undefined) { name = messageData.target; } + text = _.sprintf(gettext("Now updating %(name)s to %(version)s"), {name: name, version: messageData.version}); + self.loglines.push({line: "", stream: "separator"}); + self.loglines.push({line: _.repeat("+", text.length), stream: "separator"}); + self.loglines.push({line: text, stream: "message"}); + self.loglines.push({line: _.repeat("+", text.length), stream: "separator"}); self._updatePopup({ text: text, hide: false, @@ -339,14 +405,18 @@ $(function() { sticker: false } }); + break; } case "restarting": { console.log(JSON.stringify(messageData)); + title = gettext("Update successful, restarting!"); + text = gettext("The update finished successfully and the server will now be restarted."); + options = { - title: gettext("Update successful, restarting!"), - text: gettext("The update finished successfully and the server will now be restarted."), + title: title, + text: text, type: "success", hide: false, buttons: { @@ -354,11 +424,16 @@ $(function() { } }; + self.loglines.push({line: text, stream: "message"}); + self.waitingForRestart = true; self.restartTimeout = setTimeout(function() { + title = gettext("Restart failed"); + text = gettext("The server apparently did not restart by itself, you'll have to do it manually. Please consult the log file on what went wrong."); + self._showPopup({ - title: gettext("Restart failed"), - text: gettext("The server apparently did not restart by itself, you'll have to do it manually. Please consult the log file on what went wrong."), + title: title, + text: text, type: "error", hide: false, buttons: { @@ -366,21 +441,24 @@ $(function() { } }); self.waitingForRestart = false; - }, 20000); + + self._markDone(text, "message_error"); + }, 30000); break; } case "restart_manually": { console.log(JSON.stringify(messageData)); - var restartType = messageData.restart_type; - var text = gettext("The update finished successfully, please restart OctoPrint now."); + restartType = messageData.restart_type; + text = gettext("The update finished successfully, please restart OctoPrint now."); if (restartType == "environment") { text = gettext("The update finished successfully, please reboot the server now."); } + title = gettext("Update successful, restart required!"); options = { - title: gettext("Update successful, restart required!"), + title: title, text: text, type: "success", hide: false, @@ -389,18 +467,20 @@ $(function() { } }; self.updateInProgress = false; + self._markDone(text); break; } case "restart_failed": { - var restartType = messageData.restart_type; - var text = gettext("Restarting OctoPrint failed, please restart it manually. You might also want to consult the log file on what went wrong here."); + restartType = messageData.restart_type; + text = gettext("Restarting OctoPrint failed, please restart it manually. You might also want to consult the log file on what went wrong here."); if (restartType == "environment") { text = gettext("Rebooting the server failed, please reboot it manually. You might also want to consult the log file on what went wrong here."); } + title = gettext("Restart failed"); options = { - title: gettext("Restart failed"), - test: gettext("The server apparently did not restart by itself, you'll have to do it manually. Please consult the log file on what went wrong."), + title: title, + test: text, type: "error", hide: false, buttons: { @@ -409,12 +489,15 @@ $(function() { }; self.waitingForRestart = false; self.updateInProgress = false; + self._markDone(text, "message_error"); break; } case "success": { + title = gettext("Update successful!"); + text = gettext("The update finished successfully."); options = { - title: gettext("Update successful!"), - text: gettext("The update finished successfully."), + title: title, + text: text, type: "success", hide: false, buttons: { @@ -422,12 +505,15 @@ $(function() { } }; self.updateInProgress = false; + self._markDone(text); break; } case "error": { + title = gettext("Update failed!"); + text = gettext("The update did not finish successfully. Please consult the log for details."); self._showPopup({ - title: gettext("Update failed!"), - text: gettext("The update did not finish successfully. Please consult the log for details."), + title: title, + text: text, type: "error", hide: false, buttons: { @@ -435,6 +521,7 @@ $(function() { } }); self.updateInProgress = false; + self._markDone(text, "message_error"); break; } case "update_versions": { diff --git a/src/octoprint/plugins/softwareupdate/static/less/softwareupdate.less b/src/octoprint/plugins/softwareupdate/static/less/softwareupdate.less index 50939bae..1c95b4d8 100644 --- a/src/octoprint/plugins/softwareupdate/static/less/softwareupdate.less +++ b/src/octoprint/plugins/softwareupdate/static/less/softwareupdate.less @@ -1,3 +1,33 @@ td.settings_plugin_softwareupdate_column_update { width: 16px; -} \ No newline at end of file +} + +#settings_plugin_softwareupdate_workingdialog_output { + font-size: 0.8em; + + .message { + font-weight: bold; + } + + .separator { + font-weight: bold; + color: #666666; + } + + .stdout { + color: #333333; + } + + .stderr { + color: #990000; + } + + .call { + color: #000099; + } + + .message_error { + .message; + .stderr; + } +} diff --git a/src/octoprint/plugins/softwareupdate/templates/softwareupdate_settings.jinja2 b/src/octoprint/plugins/softwareupdate/templates/softwareupdate_settings.jinja2 index 96f01713..cee30242 100644 --- a/src/octoprint/plugins/softwareupdate/templates/softwareupdate_settings.jinja2 +++ b/src/octoprint/plugins/softwareupdate/templates/softwareupdate_settings.jinja2 @@ -84,3 +84,16 @@ + + diff --git a/src/octoprint/plugins/softwareupdate/updaters/pip.py b/src/octoprint/plugins/softwareupdate/updaters/pip.py index 36f52812..b3fbdb5e 100644 --- a/src/octoprint/plugins/softwareupdate/updaters/pip.py +++ b/src/octoprint/plugins/softwareupdate/updaters/pip.py @@ -27,15 +27,12 @@ def _get_pip_caller(command=None): if not key in _pip_callers: try: _pip_callers[key] = PipCaller(configured=command) - _pip_callers[key].on_log_call = _log_call - _pip_callers[key].on_log_stdout = _log_stdout - _pip_callers[key].on_log_stderr = _log_stderr except UnknownPip: _pip_callers[key] = None return _pip_callers[key] -def perform_update(target, check, target_version): +def perform_update(target, check, target_version, log_cb=None): pip_command = None if "pip_command" in check: pip_command = check["pip_command"] @@ -44,6 +41,25 @@ def perform_update(target, check, target_version): if pip_caller is None: raise RuntimeError("Can't run pip") + def _log_call(*lines): + _log(lines, prefix=" ", stream="call") + + def _log_stdout(*lines): + _log(lines, prefix=">", stream="stdout") + + def _log_stderr(*lines): + _log(lines, prefix="!", stream="stderr") + + def _log(lines, prefix=None, stream=None): + if log_cb is None: + return + log_cb(lines, prefix=prefix, stream=stream) + + if log_cb is not None: + pip_caller.on_log_call = _log_call + pip_caller.on_log_stdout = _log_stdout + pip_caller.on_log_stderr = _log_stderr + install_arg = check["pip"].format(target_version=target_version) logger.debug("Target: %s, executing pip install %s" % (target, install_arg)) @@ -57,18 +73,3 @@ def perform_update(target, check, target_version): pip_caller.execute(*pip_args) return "ok" - -def _log_call(*lines): - _log(lines, prefix=" ") - -def _log_stdout(*lines): - _log(lines, prefix=">") - -def _log_stderr(*lines): - _log(lines, prefix="!") - -def _log(lines, prefix=None): - lines = map(lambda x: x.strip(), lines) - for line in lines: - console_logger.debug(u"{prefix} {line}".format(**locals())) - diff --git a/src/octoprint/plugins/softwareupdate/updaters/python_updater.py b/src/octoprint/plugins/softwareupdate/updaters/python_updater.py index 5c9c1d9c..c865baeb 100644 --- a/src/octoprint/plugins/softwareupdate/updaters/python_updater.py +++ b/src/octoprint/plugins/softwareupdate/updaters/python_updater.py @@ -10,5 +10,5 @@ def can_perform_update(target, check): return "python_updater" in check and check["python_updater"] is not None -def perform_update(target, check, target_version): - return check["python_updater"].perform_update(target, check, target_version) \ No newline at end of file +def perform_update(target, check, target_version, log_cb=None): + return check["python_updater"].perform_update(target, check, target_version, log_cb=None) diff --git a/src/octoprint/plugins/softwareupdate/updaters/update_script.py b/src/octoprint/plugins/softwareupdate/updaters/update_script.py index 4d6f69d4..a8869e44 100644 --- a/src/octoprint/plugins/softwareupdate/updaters/update_script.py +++ b/src/octoprint/plugins/softwareupdate/updaters/update_script.py @@ -8,15 +8,39 @@ __copyright__ = "Copyright (C) 2014 The OctoPrint Project - Released under terms import sys import logging -from ..exceptions import ScriptError, ConfigurationInvalid, UpdateError -from ..util import execute +from ..exceptions import ConfigurationInvalid, UpdateError + +from octoprint.util.commandline import CommandlineCaller, CommandlineError + + +def _get_caller(log_cb=None): + def _log_call(*lines): + _log(lines, prefix=" ", stream="call") + + def _log_stdout(*lines): + _log(lines, prefix=">", stream="stdout") + + def _log_stderr(*lines): + _log(lines, prefix="!", stream="stderr") + + def _log(lines, prefix=None, stream=None): + if log_cb is None: + return + log_cb(lines, prefix=prefix, stream=stream) + + caller = CommandlineCaller() + if log_cb is not None: + caller.on_log_call = _log_call + caller.on_log_stdout = _log_stdout + caller.on_log_stderr = _log_stderr + return caller def can_perform_update(target, check): return "update_script" in check and ("checkout_folder" in check or "update_folder" in check) -def perform_update(target, check, target_version): +def perform_update(target, check, target_version, log_cb=None): logger = logging.getLogger("octoprint.plugins.softwareupdate.updaters.update_script") if not can_perform_update(target, check): @@ -27,35 +51,26 @@ def perform_update(target, check, target_version): pre_update_script = check["pre_update_script"] if "pre_update_script" in check else None post_update_script = check["post_update_script"] if "post_update_script" in check else None - update_stdout = "" - update_stderr = "" + caller = _get_caller(log_cb=log_cb) ### pre update if pre_update_script is not None: logger.debug("Target: %s, running pre-update script: %s" % (target, pre_update_script)) try: - returncode, stdout, stderr = execute(pre_update_script, cwd=folder) - update_stdout += stdout - update_stderr += stderr - except ScriptError as e: + caller.checked_call(pre_update_script, cwd=folder) + except CommandlineError as e: logger.exception("Target: %s, error while executing pre update script, got returncode %r" % (target, e.returncode)) - logger.warn("Target: %s, pre-update stdout:\n%s" % (target, e.stdout)) - logger.warn("Target: %s, pre-update stderr:\n%s" % (target, e.stderr)) ### update try: update_command = update_script.format(python=sys.executable, folder=folder, target=target_version) - logger.debug("Target %s, running update script: %s" % (target, update_command)) - returncode, stdout, stderr = execute(update_command, cwd=folder) - update_stdout += stdout - update_stderr += stderr - except ScriptError as e: + + caller.checked_call(update_command, cwd=folder) + except CommandlineError as e: logger.exception("Target: %s, error while executing update script, got returncode %r" % (target, e.returncode)) - logger.warn("Target: %s, update stdout:\n%s" % (target, e.stdout)) - logger.warn("Target: %s, update stderr:\n%s" % (target, e.stderr)) raise UpdateError("Error while executing update script for %s", (e.stdout, e.stderr)) ### post update @@ -63,17 +78,8 @@ def perform_update(target, check, target_version): if post_update_script is not None: logger.debug("Target: %s, running post-update script %s..." % (target, post_update_script)) try: - returncode, stdout, stderr = execute(post_update_script, cwd=folder) - update_stdout += stdout - update_stderr += stderr - except ScriptError as e: + caller.checked_call(post_update_script, cwd=folder) + except CommandlineError as e: logger.exception("Target: %s, error while executing post update script, got returncode %r" % (target, e.returncode)) - logger.warn("Target: %s, post-update stdout:\n%s" % (target, e.stdout)) - logger.warn("Target: %s, post-update stderr:\n%s" % (target, e.stderr)) - logger.debug("Target: %s, update stdout:\n%s" % (target, update_stdout)) - logger.debug("Target: %s, update stderr:\n%s" % (target, update_stderr)) - - ### result - - return update_stdout, update_stderr + return "ok"