log: Sud lifecycle transitions and stirrer/heater connect state

Logs load/start/pause/continue/stop/entering-step/wait-user/finished
on Sud (components/sud.py) and connected/disconnected on
StirrerTask/HeaterTask, using the self.log added earlier.

SudForecastEstimator.estimate() (components/sud_forecast.py) drives its
own throwaway Sud through an entire schedule in a tight loop (no real
waiting) to predict its duration, and re-runs that on every real step
transition too - since it's still a Sud, it logged through the exact
same "Sud" logger as the real, server-driven one, making an instant
internal forecast run indistinguishable in the log from an actual
brew. Gave it its own "SudForecastEstimator" logger, silenced to
WARNING by default, so only the real Sud's transitions show up.

components/sud.py

@@ -154,6 +154,7 @@ class Sud(AttributeChange):
 		self._data = data
 
 		self._reset_run_state()
+		self.log.info("Loaded '{}'".format(self.name))
 		return True
 
 	def derive_plant_params(self, grain_mass, water_mass):
@@ -183,11 +184,13 @@ class Sud(AttributeChange):
 		if self.state == SudState.PAUSED:
 			self.state = self._paused_from
 			self._paused_from = None
+			self.log.info("Continued")
 			return
 		if self.state not in (SudState.IDLE, SudState.DONE):
 			return
 		self.index = -1
 		self.elapsed = 0.0
+		self.log.info("Started")
 		self._advance()
 
 	def pause(self):
@@ -196,11 +199,13 @@ class Sud(AttributeChange):
 		if self.state in (SudState.RAMPING, SudState.HOLDING):
 			self._paused_from = self.state
 			self.state = SudState.PAUSED
+			self.log.info("Paused")
 
 	def stop(self):
 		"""Aborts the run, discarding progress back to IDLE."""
 		if self.state not in (SudState.IDLE, SudState.DONE):
 			self._reset_run_state()
+			self.log.info("Stopped")
 
 	def confirm(self):
 		if self.state == SudState.WAIT_USER:
@@ -243,6 +248,7 @@ class Sud(AttributeChange):
 			self.state = SudState.DONE
 			self.user_message = None
 			self.step = None
+			self.log.info("Finished")
 			return
 
 		next_step = self.schedule[self.index]
@@ -254,9 +260,11 @@ class Sud(AttributeChange):
 		self.state = SudState.RAMPING
 		self.user_message = next_step.get('user_message')
 		self.step = next_step
+		self.log.info("Entering step {} ({})".format(next_step['number'], next_step.get('descr')))
 
 	def _finish_step(self):
 		if self.step.get('user_wait_for_continue', False):
 			self.state = SudState.WAIT_USER
+			self.log.info("Waiting for user interaction")
 		else:
 			self._advance()

components/sud_forecast.py

@@ -1,3 +1,4 @@
+import logging
 from components.plant import Pot
 from components.pid import PidFactory
 from components.sud import Sud, SudState
@@ -7,6 +8,14 @@ from components.sud import Sud, SudState
 # simulation forever - the estimate is simply cut off there.
 MAX_TICKS = 200000
 
+# estimate() below drives a throwaway Sud through an entire schedule in a
+# tight loop (no real waiting) purely to predict its duration - since it's
+# still a Sud, it would otherwise log through the exact same "Sud" logger
+# the real, server-driven one uses (components/sud.py's self.log), making
+# an instant internal forecast run indistinguishable in the log from an
+# actual brew. Quiet by default; raise this logger's own level to see it.
+logging.getLogger('SudForecastEstimator').setLevel(logging.WARNING)
+
 # Mirrors tasks/heater.py's own pulse_period_s - HeaterTask duty-cycles its
 # device's discrete power steps over a rolling window this many *real*
 # seconds wide, regardless of warp factor (see estimate()'s actuate()
@@ -95,6 +104,7 @@ class SudForecastEstimator:
 			start_theta = self.theta_amb
 
 		sud = Sud(self.pot_config)
+		sud.log = logging.getLogger('SudForecastEstimator')
 		if not sud.load(doc) or not sud.schedule:
 			return [0.0], [start_theta], SudState.DONE, {}
 

tasks/heater.py

@@ -33,6 +33,7 @@ class HeaterTask(ATask):
 		self._on_connected_changed = callback
 
 	def on_connected_changed(self, value):
+		self.log.info("Connected" if value else "Disconnected")
 		fire_and_forget(self.send({'Connected': value}))
 		if self._on_connected_changed:
 			self._on_connected_changed(value)

tasks/stirrer.py

@@ -33,6 +33,7 @@ class StirrerTask(ATask):
 		self._on_connected_changed = callback
 
 	def on_connected_changed(self, value):
+		self.log.info("Connected" if value else "Disconnected")
 		fire_and_forget(self.send({'Connected': value}))
 		if self._on_connected_changed:
 			self._on_connected_changed(value)