brewpi/tasks/server_log.py

import asyncio
import json
import os
import time
from tasks import ATask
from components import APid, AHeater


class ServerLogTask(ATask):
	"""Continuously records temp/power samples from server start to shutdown.

	Writes a single log_{date_time}.json on close() in the same format as
	SudLogTask (Name/Samples) so analyze_log.py and replay_sim.py can
	consume it directly.  Unlike SudLogTask, which only records during an
	active Sud run, this log covers the full server session regardless of
	Sud state — useful for verifying controller and heater behaviour
	outside of a scheduled brew."""

	def __init__(self, tc: APid, heater: AHeater, heater_task, interval, path='./logs', config=None, dt=None, log_interval=None, sim_warp_factor=None):
		ATask.__init__(self, interval)
		self.tc = tc
		self.heater = heater
		self.heater_task = heater_task
		self.path = path
		self.config = config
		self.dt = dt
		self.log_interval = log_interval
		self.sim_warp_factor = sim_warp_factor
		self._samples = []
		self._param_events = []
		self._elapsed_total = 0.0
		self._run_id = time.strftime("%Y%m%dT%H%M%S", time.localtime())
		self._last_write = time.monotonic()

	def log_plant_params(self, params):
		# Stamped with this logger's *own* _elapsed() - not, say, Sud.elapsed
		# passed in from the caller - so PlantParams' 't' always lines up
		# with this same log's own Samples' 't'. SudLogTask's _elapsed() IS
		# Sud.elapsed, but ServerLogTask's is its own independent counter
		# since server startup, on a completely different timeline (the
		# server usually starts well before any Sud does) - using the
		# wrong one made utils/replay_sim.py apply plant-param changes at
		# the wrong point in ServerLogTask's own Samples entirely.
		self._param_events.append({'t': self._elapsed(), 'params': params})

	async def on_process(self):
		while True:
			if self._should_sample():
				self._samples.append(self._take_sample())
			# Periodically checkpoints to disk (same file, overwritten whole
			# each time - see write()) so a hard crash/power loss only loses
			# up to log_interval seconds, not the whole session/run. This
			# checkpoint cadence is deliberately real (wall-clock) time,
			# unlike _elapsed() below - it's bounding real data-loss risk,
			# not tracking brew progress.
			now = time.monotonic()
			# Gated on _should_sample(): for SudLogTask, a completed run's
			# stop_run() already wrote the correct final state and cleared
			# _param_events for the *next* run - an unguarded checkpoint
			# here would otherwise fire on the very next iteration (once
			# log_interval real seconds have passed since the last one,
			# regardless of the run having ended in between) and clobber
			# that already-correct file with _samples unchanged but
			# _param_events now empty.
			if self.log_interval and self._should_sample() and now - self._last_write >= self.log_interval:
				self.write()
				self._last_write = now
			await asyncio.sleep(self.interval)
			self._elapsed_total += self.dt

	def _should_sample(self):
		return True

	def _elapsed(self):
		"""Simulated seconds elapsed since this task started sampling -
		tick-counted (advances by self.dt once per on_process() iteration),
		never derived from wall-clock time: under sim_warp_factor, real and
		simulated time diverge (see components/sud.py's Sud.elapsed, and
		the README's "Forecast vs. actual duration" section, for the same
		reasoning), so a wall-clock 't' would desync from the forecast's
		own tick-counted timeline it's meant to be compared against."""
		return self._elapsed_total

	def _take_sample(self):
		power_set = max(self.heater_task.power_soll, self.heater_task.power_actor)
		return {
			't':         self._elapsed(),
			'timestamp': time.time(),
			'temp_ist':  self.tc.theta_ist,
			'temp_soll': self.tc.theta_soll_set,
			'rate_ist':  self.tc.heatrate_ist,
			'rate_soll': self.tc.heatrate_soll,
			'power_set': power_set,
			'power_eff': self.heater.power_eff,
		}

	def _filename(self):
		return 'log_{}.json'.format(self._run_id)

	def _latest_filename(self):
		"""Fixed (no-date) name written alongside the dated one on every
		write() - always overwritten, so a dashboard/tail-style consumer
		can point at one unchanging path instead of tracking the current
		run's own timestamped filename."""
		return 'log_latest.json'

	def _extra_log_data(self):
		"""Hook for subclasses (SudLogTask) to contribute additional keys
		to write()'s output - see there."""
		return {}

	def _log_name(self):
		"""Hook for subclasses (SudLogTask) - a server-session log covers
		the whole process lifetime rather than one named run, so it has
		none of its own."""
		return ''

	def write(self):
		if not self._samples:
			return
		os.makedirs(self.path, exist_ok=True)
		filename = self._filename()
		log_data = {'Name': self._log_name()}
		if self.dt is not None:
			log_data['dt'] = self.dt
		if self.sim_warp_factor is not None:
			log_data['SimWarpFactor'] = self.sim_warp_factor
		if self.config is not None:
			log_data['Config'] = self.config
		# Queried live from the connected device rather than reconstructed
		# offline (utils/analyze_log.py has no hardware to ask) - needed to
		# reproduce this run's SudForecastEstimator (see components/
		# sud_forecast.py) for a post-hoc forecast-vs-actual comparison.
		log_data['HeaterPowers'] = self.heater.get_powers()
		if self._param_events:
			log_data['PlantParams'] = self._param_events
		log_data.update(self._extra_log_data())
		log_data['Samples'] = self._samples
		# Written to both the dated filename (this run/session's own
		# permanent record) and a fixed, always-overwritten one (see
		# _latest_filename()) - same content, so a consumer wanting
		# "whatever's most current" never has to track the dated name.
		for name in (filename, self._latest_filename()):
			with open(os.path.join(self.path, name), 'w') as f:
				json.dump(log_data, f, indent='\t')
		self.log.info('Wrote {} samples to {}'.format(len(self._samples), filename))