SWU: plugin now logs stdout/stderr during updating

Only if logged in as Admin though. Working dialog is as verbose as
Plugin install dialog.
This commit is contained in:
Gina Häußge 2015-07-03 13:59:22 +02:00
parent ae73ebdcb3
commit be8827b67c
8 changed files with 239 additions and 78 deletions

View file

@ -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

View file

@ -1 +1 @@
td.settings_plugin_softwareupdate_column_update{width:16px}
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}

View file

@ -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": {

View file

@ -1,3 +1,33 @@
td.settings_plugin_softwareupdate_column_update {
width: 16px;
}
}
#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;
}
}

View file

@ -84,3 +84,16 @@
</div>
</div>
<div id="settings_plugin_softwareupdate_workingdialog" class="modal hide fade">
<div class="modal-header">
<a href="#" class="close" data-dismiss="modal" aria-hidden="true">&times;</a>
<h3 data-bind="text: workingTitle"></h3>
</div>
<div class="modal-body">
<pre id="settings_plugin_softwareupdate_workingdialog_output" class="terminal pre-scrollable" style="height: 170px" data-bind="foreach: loglines"><span data-bind="text: line, css: {stdout: stream == 'stdout', stderr: stream == 'stderr', call: stream == 'call', message: stream == 'message'}"></span><br></pre>
</div>
<div class="modal-footer">
<button class="btn" data-dismiss="modal" data-bind="enable: !$root.working()" aria-hidden="true">{{ _('Close') }}</button>
</div>
</div>

View file

@ -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()))

View file

@ -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)
def perform_update(target, check, target_version, log_cb=None):
return check["python_updater"].perform_update(target, check, target_version, log_cb=None)

View file

@ -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"