Revamped gcode analysis.

Now UI and backend take data from saved metadata (if available). Metadata gets written after file upload and also on startup (for files that have not been added yet). Gcode analysis is interrupted if a printjob is started and resumed when it ends. Frontend is notified when new metadata comes available and UI triggers reload of gcode file list.  Also started on implementing proper logging.

octoprint/gcodefiles.py

@@ -8,6 +8,7 @@ import threading
 import datetime
 import yaml
 import time
+import logging
 import octoprint.util as util
 import octoprint.util.gcodeInterpreter as gcodeInterpreter
 from octoprint.settings import settings
@@ -16,8 +17,12 @@ from werkzeug.utils import secure_filename
 
 class GcodeManager:
 	def __init__(self):
+		self._logger = logging.getLogger(__name__)
+
 		self._uploadFolder = settings().getBaseFolder("uploads")
 
+		self._callbacks = []
+
 		self._metadata = {}
 		self._metadataDirty = False
 		self._metadataFile = os.path.join(self._uploadFolder, "metadata.yaml")
@@ -26,9 +31,22 @@ class GcodeManager:
 		self._metadataAnalyzer = MetadataAnalyzer(getPathCallback=self.getAbsolutePath, loadedCallback=self._onMetadataAnalysisFinished)
 
 		self._loadMetadata()
+		self._processAnalysisBacklog()
+
+	def _processAnalysisBacklog(self):
+		for osFile in os.listdir(self._uploadFolder):
+			filename = self._getBasicFilename(osFile)
+			absolutePath = self.getAbsolutePath(filename)
+			if absolutePath is None:
+				continue
+
+			fileData = self.getFileData(filename)
+			if fileData is not None and "gcodeAnalysis" in fileData.keys():
+				continue
+
+			self._metadataAnalyzer.addFileToBacklog(filename)
 
 	def _onMetadataAnalysisFinished(self, filename, gcode):
-		print("Got gcode analysis for file %s: %r" % (filename, gcode))
 		if filename is None or gcode is None:
 			return
 
@@ -59,6 +77,8 @@ class GcodeManager:
 			with self._metadataFileAccessMutex:
 				with open(self._metadataFile, "r") as f:
 					self._metadata = yaml.safe_load(f)
+		if self._metadata is None:
+			self._metadata = {}
 
 	def _saveMetadata(self, force=False):
 		if not self._metadataDirty and not force:
@@ -69,6 +89,7 @@ class GcodeManager:
 				yaml.safe_dump(self._metadata, f, default_flow_style=False, indent="    ", allow_unicode=True)
 				self._metadataDirty = False
 		self._loadMetadata()
+		self._sendUpdateTrigger("gcodeFiles")
 
 	def _getBasicFilename(self, filename):
 		if filename.startswith(self._uploadFolder):
@@ -76,6 +97,22 @@ class GcodeManager:
 		else:
 			return filename
 
+	#~~ callback handling
+
+	def registerCallback(self, callback):
+		self._callbacks.append(callback)
+
+	def unregisterCallback(self, callback):
+		if callback in self._callbacks:
+			self._callbacks.remove(callback)
+
+	def _sendUpdateTrigger(self, type):
+		for callback in self._callbacks:
+			try: callback.sendUpdateTrigger(type)
+			except: pass
+
+	#~~ file handling
+
 	def addFile(self, file):
 		if file:
 			absolutePath = self.getAbsolutePath(file.filename, mustExist=False)
@@ -90,6 +127,10 @@ class GcodeManager:
 		absolutePath = self.getAbsolutePath(filename)
 		if absolutePath is not None:
 			os.remove(absolutePath)
+			if filename in self._metadata.keys():
+				del self._metadata[filename]
+				self._metadataDirty = True
+				self._saveMetadata()
 
 	def getAbsolutePath(self, filename, mustExist=True):
 		"""
@@ -177,6 +218,8 @@ class GcodeManager:
 		self._metadata[filename] = metadata
 		self._metadataDirty = True
 
+	#~~ print job data
+
 	def printSucceeded(self, filename):
 		filename = self._getBasicFilename(filename)
 		absolutePath = self.getAbsolutePath(filename)
@@ -207,8 +250,18 @@ class GcodeManager:
 		self.setFileMetadata(filename, metadata)
 		self._saveMetadata()
 
+	#~~ analysis control
+
+	def pauseAnalysis(self):
+		self._metadataAnalyzer.pause()
+
+	def resumeAnalysis(self):
+		self._metadataAnalyzer.resume()
+
 class MetadataAnalyzer:
 	def __init__(self, getPathCallback, loadedCallback):
+		self._logger = logging.getLogger(__name__)
+
 		self._getPathCallback = getPathCallback
 		self._loadedCallback = loadedCallback
 
@@ -218,7 +271,7 @@ class MetadataAnalyzer:
 		self._currentFile = None
 		self._currentProgress = None
 
-		self._queue = Queue.Queue()
+		self._queue = Queue.PriorityQueue()
 		self._gcode = None
 
 		self._worker = threading.Thread(target=self._work)
@@ -226,7 +279,12 @@ class MetadataAnalyzer:
 		self._worker.start()
 
 	def addFileToQueue(self, filename):
-		self._queue.put(filename)
+		self._logger.debug("Adding file %s to analysis queue (high priority)" % filename)
+		self._queue.put((0, filename))
+
+	def addFileToBacklog(self, filename):
+		self._logger.debug("Adding file %s to analysis backlog (low priority)" % filename)
+		self._queue.put((100, filename))
 
 	def working(self):
 		return self.isActive() and not (self._queue.empty() and self._currentFile is None)
@@ -235,11 +293,14 @@ class MetadataAnalyzer:
 		return self._active.is_set()
 
 	def pause(self):
+		self._logger.debug("Pausing Gcode analyzer")
 		self._active.clear()
 		if self._gcode is not None:
+			self._logger.debug("Aborting running analysis, will restart when Gcode analyzer is resumed")
 			self._gcode.abort()
 
 	def resume(self):
+		self._logger.debug("Resuming Gcode analyzer")
 		self._active.set()
 
 	def _work(self):
@@ -250,14 +311,17 @@ class MetadataAnalyzer:
 			if aborted is not None:
 				filename = aborted
 				aborted = None
+				self._logger.debug("Got an aborted analysis job for file %s, processing this instead of first item in queue" % filename)
 			else:
-				filename = self._queue.get()
+				(priority, filename) = self._queue.get()
+				self._logger.debug("Processing file %s from queue (priority %d)" % (filename, priority))
 
 			try:
 				self._analyzeGcode(filename)
 				self._queue.task_done()
 			except gcodeInterpreter.AnalysisAborted:
 				aborted = filename
+				self._logger.debug("Running analysis of file %s aborted" % filename)
 
 	def _analyzeGcode(self, filename):
 		path = self._getPathCallback(filename)
@@ -268,9 +332,11 @@ class MetadataAnalyzer:
 		self._currentProgress = 0
 
 		try:
+			self._logger.debug("Starting analysis of file %s" % filename)
 			self._gcode = gcodeInterpreter.gcode()
 			self._gcode.progressCallback = self._onParsingProgress
 			self._gcode.load(path)
+			self._logger.debug("Analysis of file %s finished, notifying callback" % filename)
 			self._loadedCallback(self._currentFile, self._gcode)
 		finally:
 			self._gcode = None

octoprint/printer.py

@@ -10,7 +10,6 @@ import os
 
 import octoprint.util.comm as comm
 import octoprint.util as util
-from octoprint.util import gcodeInterpreter
 
 from octoprint.settings import settings
 
@@ -59,7 +58,6 @@ class Printer():
 		self._printTimeLeft = None
 
 		# gcode handling
-		self._gcode = None
 		self._gcodeList = None
 		self._filename = None
 		self._gcodeLoader = None
@@ -168,7 +166,7 @@ class Printer():
 		if (self._comm is not None and self._comm.isPrinting()) or (self._gcodeLoader is not None):
 			return
 
-		self._setJobData(None, None, None)
+		self._setJobData(None, None)
 
 		self._gcodeLoader = GcodeLoader(file, self._onGcodeLoadingProgress, self._onGcodeLoaded)
 		self._gcodeLoader.start()
@@ -285,31 +283,28 @@ class Printer():
 
 		self._stateMonitor.addTemperature({"currentTime": currentTimeUtc, "temp": self._temp, "bedTemp": self._bedTemp, "targetTemp": self._targetTemp, "targetBedTemp": self._targetBedTemp})
 
-	def _setJobData(self, filename, gcode, gcodeList):
+	def _setJobData(self, filename, gcodeList):
 		self._filename = filename
-		self._gcode = gcode
 		self._gcodeList = gcodeList
 
 		lines = None
 		if self._gcodeList:
 			lines = len(self._gcodeList)
 
-		formattedPrintTimeEstimation = None
-		formattedFilament = None
-		if self._gcode:
-			if self._gcode.totalMoveTimeMinute:
-				formattedPrintTimeEstimation = util.getFormattedTimeDelta(datetime.timedelta(minutes=self._gcode.totalMoveTimeMinute))
-			if self._gcode.extrusionAmount:
-				formattedFilament = "%.2fm" % (self._gcode.extrusionAmount / 1000)
-		elif not settings().getBoolean("feature", "analyzeGcode"):
-			formattedPrintTimeEstimation = "unknown"
-			formattedFilament = "unknown"
-
 		formattedFilename = None
+		estimatedPrintTime = None
+		filament = None
 		if self._filename:
 			formattedFilename = os.path.basename(self._filename)
 
-		self._stateMonitor.setJobData({"filename": formattedFilename, "lines": lines, "estimatedPrintTime": formattedPrintTimeEstimation, "filament": formattedFilament})
+			fileData = self._gcodeManager.getFileData(filename)
+			if fileData is not None and "gcodeAnalysis" in fileData.keys():
+				if "estimatedPrintTime" in fileData["gcodeAnalysis"].keys():
+					estimatedPrintTime = fileData["gcodeAnalysis"]["estimatedPrintTime"]
+				if "filament" in fileData["gcodeAnalysis"].keys():
+					filament = fileData["gcodeAnalysis"]["filament"]
+
+		self._stateMonitor.setJobData({"filename": formattedFilename, "lines": lines, "estimatedPrintTime": estimatedPrintTime, "filament": filament})
 
 	def _sendInitialStateUpdate(self, callback):
 		try:
@@ -353,18 +348,22 @@ class Printer():
 		"""
 		oldState = self._state
 
-		#
+		# forward relevant state changes to timelapse
 		if self._timelapse is not None:
 			if oldState == self._comm.STATE_PRINTING and state != self._comm.STATE_PAUSED:
 				self._timelapse.onPrintjobStopped()
 			elif state == self._comm.STATE_PRINTING and oldState != self._comm.STATE_PAUSED:
 				self._timelapse.onPrintjobStarted(self._filename)
 
+		# forward relevant state changes to gcode manager
 		if oldState == self._comm.STATE_PRINTING:
 			if state == self._comm.STATE_OPERATIONAL:
 				self._gcodeManager.printSucceeded(self._filename)
 			elif state == self._comm.STATE_CLOSED or state == self._comm.STATE_ERROR or state == self._comm.STATE_CLOSED_WITH_ERROR:
 				self._gcodeManager.printFailed(self._filename)
+			self._gcodeManager.resumeAnalysis() # do not analyse gcode while printing
+		elif state == self._comm.STATE_PRINTING:
+			self._gcodeManager.pauseAnalysis() # printing done, put those cpu cycles to good use
 
 		self._setState(state)
 
@@ -408,12 +407,8 @@ class Printer():
 
 		self._stateMonitor.setGcodeData({"filename": formattedFilename, "progress": progress, "mode": mode})
 
-	def _onGcodeLoaded(self, filename, gcode, gcodeList):
+	def _onGcodeLoaded(self, filename, gcodeList):
-		formattedFilename = None
+		self._setJobData(filename, gcodeList)
-		if filename is not None:
-			formattedFilename = os.path.basename(filename)
-
-		self._setJobData(formattedFilename, gcode, gcodeList)
 		self._setCurrentZ(None)
 		self._setProgressData(None, None, None)
 		self._gcodeLoader = None
@@ -480,7 +475,6 @@ class GcodeLoader(threading.Thread):
 		self._loadedCallback = loadedCallback
 
 		self._filename = filename
-		self._gcode = None
 		self._gcodeList = None
 
 	def run(self):
@@ -504,12 +498,7 @@ class GcodeLoader(threading.Thread):
 				self._onLoadingProgress(float(file.tell()) / float(filesize))
 
 		self._gcodeList = gcodeList
-		if settings().getBoolean("feature", "analyzeGcode"):
+		self._loadedCallback(self._filename, self._gcodeList)
-			self._gcode = gcodeInterpreter.gcode()
-			self._gcode.progressCallback = self._onParsingProgress
-			self._gcode.loadList(self._gcodeList)
-
-		self._loadedCallback(self._filename, self._gcode, self._gcodeList)
 
 	def _onLoadingProgress(self, progress):
 		self._progressCallback(self._filename, progress, "loading")
@@ -517,22 +506,6 @@ class GcodeLoader(threading.Thread):
 	def _onParsingProgress(self, progress):
 		self._progressCallback(self._filename, progress, "parsing")
 
-class PrinterCallback(object):
-	def sendCurrentData(self, data):
-		pass
-
-	def sendHistoryData(self, data):
-		pass
-
-	def addTemperature(self, data):
-		pass
-
-	def addLog(self, data):
-		pass
-
-	def addMessage(self, data):
-		pass
-
 class StateMonitor(object):
 	def __init__(self, ratelimit, updateCallback, addTemperatureCallback, addLogCallback, addMessageCallback):
 		self._ratelimit = ratelimit

octoprint/server.py

@@ -8,8 +8,9 @@ import tornadio2
 
 import os
 import threading
+import logging, logging.config
 
-from octoprint.printer import Printer, getConnectionOptions, PrinterCallback
+from octoprint.printer import Printer, getConnectionOptions
 from octoprint.settings import settings
 import octoprint.timelapse as timelapse
 import octoprint.gcodefiles as gcodefiles
@@ -29,16 +30,17 @@ def index():
 	return render_template(
 		"index.html",
 		webcamStream=settings().get("webcam", "stream"),
-		enableTimelapse=(settings().get("webcam", "snapshot") is not None and settings().get("webcam", "ffmpeg") is not None),
+		enableTimelapse=(settings().get("webcam", "snapshot") is not None and settings().get("webcam", "ffmpeg") is not None)
-		enableEstimations=(settings().getBoolean("feature", "analyzeGcode"))
 	)
 
 #~~ Printer state
 
-class PrinterStateConnection(tornadio2.SocketConnection, PrinterCallback):
+class PrinterStateConnection(tornadio2.SocketConnection):
 	def __init__(self, session, endpoint=None):
 		tornadio2.SocketConnection.__init__(self, session, endpoint)
 
+		self._logger = logging.getLogger(__name__)
+
 		self._temperatureBacklog = []
 		self._temperatureBacklogMutex = threading.Lock()
 		self._logBacklog = []
@@ -47,12 +49,14 @@ class PrinterStateConnection(tornadio2.SocketConnection, PrinterCallback):
 		self._messageBacklogMutex = threading.Lock()
 
 	def on_open(self, info):
-		print("New connection from client")
+		self._logger.info("New connection from client")
 		printer.registerCallback(self)
+		gcodeManager.registerCallback(self)
 
 	def on_close(self):
-		print("Closed client connection")
+		self._logger.info("Closed client connection")
 		printer.unregisterCallback(self)
+		gcodeManager.unregisterCallback(self)
 
 	def on_message(self, message):
 		pass
@@ -81,6 +85,9 @@ class PrinterStateConnection(tornadio2.SocketConnection, PrinterCallback):
 	def sendHistoryData(self, data):
 		self.emit("history", data)
 
+	def sendUpdateTrigger(self, type):
+		self.emit("updateTrigger", type)
+
 	def addLog(self, data):
 		with self._logBacklogMutex:
 			self._logBacklog.append(data)
@@ -334,7 +341,7 @@ def run(host = "0.0.0.0", port = 5000, debug = False):
 	from tornado.ioloop import IOLoop
 	from tornado.web import Application, FallbackHandler
 
-	print "Listening on http://%s:%d" % (host, port)
+	logging.getLogger(__name__).info("Listening on http://%s:%d" % (host, port))
 	app.debug = debug
 
 	router = tornadio2.TornadioRouter(PrinterStateConnection)
@@ -345,6 +352,34 @@ def run(host = "0.0.0.0", port = 5000, debug = False):
 	server.listen(port, address=host)
 	IOLoop.instance().start()
 
+def initLogging():
+	config = {
+		"version": 1,
+		"formatters": {
+			"simple": {
+				"format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
+			}
+		},
+		"handlers": {
+			"console": {
+				"class": "logging.StreamHandler",
+				"level": "DEBUG",
+				"formatter": "simple",
+				"stream": "ext://sys.stdout"
+			}
+		},
+		"loggers": {
+			"octoprint.gcodefiles": {
+				"level": "DEBUG"
+			}
+		},
+		"root": {
+			"level": "INFO",
+			"handlers": ["console"]
+		}
+	}
+	logging.config.dictConfig(config)
+
 def main():
 	from optparse import OptionParser
 
@@ -360,6 +395,7 @@ def main():
 		help="Specify the port on which to bind the server, defaults to %s if not set" % (defaultPort))
 	(options, args) = parser.parse_args()
 
+	initLogging()
 	run(host=options.host, port=options.port, debug=options.debug)
 
 if __name__ == "__main__":

octoprint/settings.py

@@ -39,7 +39,6 @@ old_default_settings = {
 		"timelapse_tmp": None
 	},
 	"feature": {
-		"analyzeGcode": True
 	},
 }
 

octoprint/static/css/ui.css

@@ -84,7 +84,6 @@ table th.gcode_files_action, table td.gcode_files_action {
     left: 0;
     width: 100%;
     height: 100%;
-    display: block;
     z-index: 10000;
     display: none;
 }

octoprint/static/js/ui.js

@@ -811,7 +811,7 @@ function WebcamViewModel() {
     }
 }
 
-function DataUpdater(connectionViewModel, printerStateViewModel, temperatureViewModel, controlsViewModel, speedViewModel, terminalViewModel, webcamViewModel) {
+function DataUpdater(connectionViewModel, printerStateViewModel, temperatureViewModel, controlsViewModel, speedViewModel, terminalViewModel, gcodeFilesViewModel, webcamViewModel) {
     var self = this;
 
     self.connectionViewModel = connectionViewModel;
@@ -820,6 +820,7 @@ function DataUpdater(connectionViewModel, printerStateViewModel, temperatureView
     self.controlsViewModel = controlsViewModel;
     self.terminalViewModel = terminalViewModel;
     self.speedViewModel = speedViewModel;
+    self.gcodeFilesViewModel = gcodeFilesViewModel;
     self.webcamViewModel = webcamViewModel;
 
     self._socket = io.connect();
@@ -860,6 +861,11 @@ function DataUpdater(connectionViewModel, printerStateViewModel, temperatureView
         self.terminalViewModel.fromCurrentData(data);
         self.webcamViewModel.fromCurrentData(data);
     })
+    self._socket.on("updateTrigger", function(type) {
+        if (type == "gcodeFiles") {
+            gcodeFilesViewModel.requestData();
+        }
+    })
 
     self.reconnect = function() {
         self._socket.socket.connect();
@@ -877,7 +883,16 @@ $(function() {
         var terminalViewModel = new TerminalViewModel();
         var gcodeFilesViewModel = new GcodeFilesViewModel();
         var webcamViewModel = new WebcamViewModel();
-        var dataUpdater = new DataUpdater(connectionViewModel, printerStateViewModel, temperatureViewModel, controlsViewModel, speedViewModel, terminalViewModel, webcamViewModel);
+
+        var dataUpdater = new DataUpdater(
+            connectionViewModel,
+            printerStateViewModel,
+            temperatureViewModel,
+            controlsViewModel,
+            speedViewModel,
+            terminalViewModel,
+            gcodeFilesViewModel,
+            webcamViewModel);
 
         //~~ Print job control
 
@@ -983,6 +998,23 @@ $(function() {
         //~~ Offline overlay
         $("#offline_overlay_reconnect").click(function() {dataUpdater.reconnect()});
 
+        //~~ Alert
+
+        /*
+        function displayAlert(text, timeout, type) {
+            var placeholder = $("#alert_placeholder");
+
+            var alertType = "";
+            if (type == "success" || type == "error" || type == "info") {
+                alertType = " alert-" + type;
+            }
+
+            placeholder.append($("<div id='activeAlert' class='alert " + alertType + " fade in' data-alert='alert'><p>" + text + "</p></div>"));
+            placeholder.fadeIn();
+            $("#activeAlert").delay(timeout).fadeOut("slow", function() {$(this).remove(); $("#alert_placeholder").hide();});
+        }
+        */
+
         //~~ knockout.js bindings
 
         ko.bindingHandlers.popover = {

octoprint/templates/index.html

@@ -54,10 +54,8 @@
                             <div class="accordion-inner">
                                 Machine State: <strong data-bind="text: stateString"></strong><br>
                                 File: <strong data-bind="text: filename"></strong><br>
-                                {% if enableEstimations %}
+                                Filament: <strong data-bind="text: filament"></strong><br>
-                                    Filament: <strong data-bind="text: filament"></strong><br>
+                                Estimated Print Time: <strong data-bind="text: estimatedPrintTime"></strong><br>
-                                    Estimated Print Time: <strong data-bind="text: estimatedPrintTime"></strong><br>
-                                {% endif %}
                                 Line: <strong data-bind="text: lineString"></strong><br>
                                 Height: <strong data-bind="text: currentHeight"></strong><br>
                                 Print Time: <strong data-bind="text: printTime"></strong><br>