diff --git a/Inferno.Api/Devices/Display.cs b/Inferno.Api/Devices/Display.cs index cf77158..33ae19f 100644 --- a/Inferno.Api/Devices/Display.cs +++ b/Inferno.Api/Devices/Display.cs @@ -90,9 +90,12 @@ protected virtual void Dispose(bool disposing) if (disposing) { DisplayText("Shutting down...", "", "", "Goodbye!".PadLeft(20)); - _i2c.Dispose(); + // Dispose in dependency order (mirrors Init's teardown): the LCD + // writes through the driver to the I2C bus on Dispose, so the bus + // must outlive both. Disposing _i2c first would throw here. _lcd.Dispose(); _driver.Dispose(); + _i2c.Dispose(); } disposedValue = true; } diff --git a/Inferno.Api/Devices/RtdArray.cs b/Inferno.Api/Devices/RtdArray.cs index 485c10a..9fa4146 100644 --- a/Inferno.Api/Devices/RtdArray.cs +++ b/Inferno.Api/Devices/RtdArray.cs @@ -6,6 +6,8 @@ using Inferno.Api.Interfaces; using System.Linq; using Iot.Device.Adc; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Inferno.Api.Devices { @@ -31,10 +33,12 @@ public class RtdArray : IRtdArray, IDisposable Task _adcReadTask; readonly CancellationTokenSource _stopCts = new(); + readonly ILogger _logger; - public RtdArray(SpiDevice spi) + public RtdArray(SpiDevice spi, ILogger? logger = null) { _adc = new Mcp3008(spi); + _logger = logger ?? NullLogger.Instance; _grillResistances = new ConcurrentQueue(); _probeResistances = new ConcurrentQueue(); @@ -69,7 +73,7 @@ private async Task ReadAdc() } catch (Exception ex) { - Console.WriteLine($"{DateTime.Now} {ex.Message} {ex.StackTrace}"); + _logger.LogError(ex, "ADC read failed."); try { await Task.Delay(TimeSpan.FromMilliseconds(10), _stopCts.Token); } catch (OperationCanceledException) { break; } continue; diff --git a/Inferno.Api/Pid/SmokerPid.cs b/Inferno.Api/Pid/SmokerPid.cs index 100a578..3a9379d 100644 --- a/Inferno.Api/Pid/SmokerPid.cs +++ b/Inferno.Api/Pid/SmokerPid.cs @@ -1,6 +1,7 @@ using System; -using System.Diagnostics; using Inferno.Common.Extensions; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Inferno.Api.Pid { @@ -13,16 +14,23 @@ public class SmokerPid double _integral; double _iMax = 0.5; - DateTime _lastUpdate; + // Monotonic timestamp of the last update. Using TimeProvider.GetTimestamp + // (Stopwatch-backed) instead of wall-clock DateTime keeps dt correct even when + // the Pi's clock steps on an NTP sync mid-cook. + readonly TimeProvider _timeProvider; + readonly ILogger _logger; + long _lastTimestamp; double _lastTemp; - + public double SetPoint { get; set; } - public SmokerPid(double PB, double Ti, double Td) + public SmokerPid(double PB, double Ti, double Td, TimeProvider? timeProvider = null, ILogger? logger = null) { _PB = PB; _Ti = Ti; _Td = Td; - _lastUpdate = DateTime.Now; + _timeProvider = timeProvider ?? TimeProvider.System; + _logger = logger ?? NullLogger.Instance; + _lastTimestamp = _timeProvider.GetTimestamp(); // NaN means "no valid previous sample yet" — the next reading seeds state // instead of computing a derivative/integral across an unknown gap. _lastTemp = double.NaN; @@ -30,14 +38,14 @@ public SmokerPid(double PB, double Ti, double Td) public double GetControlVariable(double currentTemp) { - DateTime now = DateTime.Now; + long now = _timeProvider.GetTimestamp(); if (double.IsNaN(currentTemp)) { // Sensor dropout: hold the integral, advance the clock, and force the // next valid reading to re-seed so we don't compute a bogus derivative // across the gap. - _lastUpdate = now; + _lastTimestamp = now; _lastTemp = double.NaN; return 0; } @@ -51,12 +59,12 @@ public double GetControlVariable(double currentTemp) // proportional-only. A stale/huge dt here would otherwise spike the // integral and derivative. _lastTemp = currentTemp; - _lastUpdate = now; - Debug.WriteLine($"u={P} (seed)"); + _lastTimestamp = now; + _logger.LogTrace("u={U} (seed)", P); return P; } - double dtSeconds = (now - _lastUpdate).TotalSeconds; + double dtSeconds = _timeProvider.GetElapsedTime(_lastTimestamp, now).TotalSeconds; double I; double D = 0; @@ -77,10 +85,10 @@ public double GetControlVariable(double currentTemp) } double u = P + I + D; - Debug.WriteLine($"u={u} ({P}+{I}+{D})"); + _logger.LogTrace("u={U} ({P}+{I}+{D})", u, P, I, D); _lastTemp = currentTemp; - _lastUpdate = now; + _lastTimestamp = now; return u; } diff --git a/Inferno.Api/Program.cs b/Inferno.Api/Program.cs index 7c1619c..3ce35d9 100644 --- a/Inferno.Api/Program.cs +++ b/Inferno.Api/Program.cs @@ -20,11 +20,23 @@ builder.Services.AddControllers(); -builder.Services.AddSingleton(new Smoker(new Auger(_gpio, 22), - new Blower(_gpio, 21), - new Igniter(_gpio, 23), - new RtdArray(_spi), - new Display())); +// Monotonic + wall clock, injectable so time-based logic can be driven in tests. +builder.Services.AddSingleton(TimeProvider.System); + +// Build the smoker from the DI container so its collaborators get real loggers +// (and journald output) instead of Debug traces that vanish in a Release build. +builder.Services.AddSingleton(sp => +{ + var loggerFactory = sp.GetRequiredService(); + var timeProvider = sp.GetRequiredService(); + return new Smoker(new Auger(_gpio, 22), + new Blower(_gpio, 21), + new Igniter(_gpio, 23), + new RtdArray(_spi, loggerFactory.CreateLogger()), + new Display(), + loggerFactory, + timeProvider); +}); var app = builder.Build(); diff --git a/Inferno.Api/Services/DisplayUpdater.cs b/Inferno.Api/Services/DisplayUpdater.cs index e1fa9bf..6ec39b0 100644 --- a/Inferno.Api/Services/DisplayUpdater.cs +++ b/Inferno.Api/Services/DisplayUpdater.cs @@ -1,7 +1,8 @@ -using System.Diagnostics; using Inferno.Api.Interfaces; using Inferno.Common.Interfaces; using Inferno.Common.Models; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Inferno.Api.Services { @@ -9,23 +10,25 @@ public class DisplayUpdater : IDisposable { ISmoker _smoker; IDisplay _display; + readonly ILogger _logger; bool _heartbeatFlag; Task _updateDisplayLoop; readonly CancellationTokenSource _stopCts = new(); - public DisplayUpdater(ISmoker smoker, IDisplay display) + public DisplayUpdater(ISmoker smoker, IDisplay display, ILogger? logger = null) { _smoker = smoker; _display = display; + _logger = logger ?? NullLogger.Instance; _heartbeatFlag = false; _updateDisplayLoop = UpdateDisplayLoop(); } private async Task UpdateDisplayLoop() { - Debug.WriteLine("Starting display thread."); + _logger.LogDebug("Starting display loop."); while (!_stopCts.IsCancellationRequested) { try @@ -70,7 +73,7 @@ private async Task UpdateDisplayLoop() } catch (Exception ex) { - Debug.WriteLine($"{DateTime.Now} Display updater exception! {ex.Message}"); + _logger.LogError(ex, "Display updater exception. Reinitializing display."); _display.Init(); } } diff --git a/Inferno.Api/Services/FireMinder.cs b/Inferno.Api/Services/FireMinder.cs index c89b34d..8a14661 100644 --- a/Inferno.Api/Services/FireMinder.cs +++ b/Inferno.Api/Services/FireMinder.cs @@ -1,8 +1,9 @@ -using System.Diagnostics; using Inferno.Api.Interfaces; using Inferno.Common.Extensions; using Inferno.Common.Interfaces; using Inferno.Common.Models; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Inferno.Api.Services { @@ -10,13 +11,24 @@ public class FireMinder : IDisposable { ISmoker _smoker; IRelayDevice _igniter; - Func _now; + // Monotonic clock: durations are measured with GetTimestamp/GetElapsedTime so + // an NTP step (the Pi has no RTC) can't spuriously trip or hang a timeout. + TimeProvider _timeProvider; + readonly ILogger _logger; LidMonitor _lidMonitor; Task _fireMinderLoop; readonly CancellationTokenSource _stopCts = new(); TimeSpan _igniterTimeout = TimeSpan.FromMinutes(10); TimeSpan _fireTimeout = TimeSpan.FromMinutes(10); /// + /// Consecutive cooking-mode ticks with an invalid grill reading before we + /// fail safe to Error. RtdArray already debounces ~2s of bad ADC reads before + /// surfacing NaN, so a few ticks here guards against a lone glitch while still + /// reacting within seconds to a genuinely dead sensor. + /// + const int SensorFaultTicks = 5; + int _invalidGrillTicks; + /// /// How long the grill must stay continuously below the fire-check temp before /// the fire is declared unhealthy. Debounces transient dips (e.g. a quick lid /// open) so we don't light the igniter on every blip — a real decline stays @@ -29,10 +41,10 @@ public class FireMinder : IDisposable /// enough to track a real climb, large enough to ignore sensor noise. /// const double RecoveryProgressF = 5.0; - DateTime _igniterOnTime; + long _igniterOnTimestamp; bool _fireCheck; - DateTime _fireCheckTime; - DateTime? _belowCheckSince; + long _fireCheckTimestamp; + long? _belowCheckSince; double _recoveryHigh; double _ignitionHigh; bool _fireStarted; @@ -61,11 +73,12 @@ public class FireMinder : IDisposable // so the Smoker stays on the aggressive RecoveryFeed instead of the floor. public bool IsLidOpen => _lidMonitor.IsLidOpen && !_fireCheck; - public FireMinder(ISmoker smoker, IRelayDevice igniter, Func? clock = null, bool autoStart = true) + public FireMinder(ISmoker smoker, IRelayDevice igniter, TimeProvider? timeProvider = null, bool autoStart = true, ILogger? logger = null) { _smoker = smoker; _igniter = igniter; - _now = clock ?? (() => DateTime.Now); + _timeProvider = timeProvider ?? TimeProvider.System; + _logger = logger ?? NullLogger.Instance; _lidMonitor = new LidMonitor(); // Tests drive Tick() directly with a controllable clock; skip the live loop. _fireMinderLoop = autoStart ? FireMinderLoop() : Task.CompletedTask; @@ -73,7 +86,7 @@ public FireMinder(ISmoker smoker, IRelayDevice igniter, Func? clock = public void ResetFireStatus() { - Debug.WriteLine("Resetting fire status."); + _logger.LogDebug("Resetting fire status."); _fireStarted = false; _fireCheck = false; _initialIgnition = true; @@ -84,6 +97,7 @@ public void ResetFireStatus() _belowCheckSince = null; _recoveryHigh = 0; _ignitionHigh = 0; + _invalidGrillTicks = 0; _lidMonitor.Reset(); } @@ -95,13 +109,18 @@ public int GetFireCheckTemp() } else { - return _smoker.SetPoint - (_smoker.SetPoint / 180 * 30); + // Fire-check temp is a fixed fraction of the setpoint: a 30F margin at + // the 180F floor (150F), scaling proportionally with setpoint. The math + // is deliberately floating-point — the old integer `SetPoint / 180` + // collapsed to a step function, putting a ~30F cliff in the threshold + // at setpoint 360. + return (int)(_smoker.SetPoint * (150.0 / 180.0)); } } private async Task FireMinderLoop() { - Debug.WriteLine("Starting Fire Minder thread."); + _logger.LogDebug("Starting Fire Minder loop."); ResetFireStatus(); while (!_stopCts.IsCancellationRequested) { @@ -116,9 +135,10 @@ private async Task FireMinderLoop() } catch (Exception ex) { - string errorText = $"{_now()} Fire Minder loop exception! {ex} {ex.StackTrace}"; - Console.WriteLine(errorText); - Debug.WriteLine(errorText); + _logger.LogError(ex, "Fire Minder loop exception."); + // Back off after a fault so a persistent throw can't hot-spin. + try { await Task.Delay(TimeSpan.FromSeconds(1), _stopCts.Token); } + catch (OperationCanceledException) { break; } } } } @@ -135,10 +155,30 @@ public void Dispose() /// internal void Tick() { + double currentGrill = _smoker.Temps.GrillTemp; + bool cooking = _smoker.Mode.IsCookingMode(); + + // Sensor-fault fail-safe: a sustained invalid grill reading during a cook + // (NaN, or the -1 "unplugged" sentinel the Smoker surfaces) means we're + // managing fire blind. Never drive ignition or the aggressive recovery + // feed off a garbage temperature — fail safe to Error, where the Smoker + // cuts fuel and igniter and runs the blower to clear the firepot. + if (cooking && (double.IsNaN(currentGrill) || currentGrill < 0)) + { + if (++_invalidGrillTicks >= SensorFaultTicks) + { + _logger.LogError("Grill sensor fault: {Ticks} consecutive invalid readings during cook. Setting error mode.", _invalidGrillTicks); + _igniter.Off(); + _smoker.SetMode(SmokerMode.Error); + } + return; + } + _invalidGrillTicks = 0; + // Feed the lid detector during cooking; otherwise keep it clear. - if (_smoker.Mode.IsCookingMode()) + if (cooking) { - _lidMonitor.Update(_smoker.Temps.GrillTemp); + _lidMonitor.Update(currentGrill); } else { @@ -155,7 +195,7 @@ internal void Tick() // The fire is not started, turn on the igniter _igniter.On(); _ignitionTemp = Math.Max(_ignitionTemp, Convert.ToInt32(grillTemp) + 10); - _igniterOnTime = _now(); + _igniterOnTimestamp = _timeProvider.GetTimestamp(); _ignitionHigh = grillTemp; } else if (grillTemp > _ignitionHigh + RecoveryProgressF) @@ -166,7 +206,7 @@ internal void Tick() // recovery path below. A truly dead light (no temperature rise) // makes no progress and still times out. _ignitionHigh = grillTemp; - _igniterOnTime = _now(); + _igniterOnTimestamp = _timeProvider.GetTimestamp(); } } @@ -180,12 +220,10 @@ internal void Tick() } if (_igniter.IsOn && - _now() - _igniterOnTime > _igniterTimeout) + _timeProvider.GetElapsedTime(_igniterOnTimestamp) > _igniterTimeout) { // The igniter has been on for too long, shut it off and go to error mode - string errorText = $"{_now()} Igniter timeout. Setting error mode."; - Debug.WriteLine(errorText); - Console.WriteLine(errorText); + _logger.LogError("Igniter timeout after {Timeout}. Setting error mode.", _igniterTimeout); _igniter.Off(); _smoker.SetMode(SmokerMode.Error); } @@ -231,15 +269,13 @@ internal void Tick() // timeout) so a slow-but-steady recovery isn't killed by a // fixed deadline. _recoveryHigh = grillTemp; - _fireCheckTime = _now(); - _igniterOnTime = _now(); + _fireCheckTimestamp = _timeProvider.GetTimestamp(); + _igniterOnTimestamp = _timeProvider.GetTimestamp(); } - else if (_now() - _fireCheckTime > _fireTimeout) + else if (_timeProvider.GetElapsedTime(_fireCheckTimestamp) > _fireTimeout) { // No upward progress for the whole timeout — the fire is out. - string errorText = $"{_now()} Fire timeout. Setting error mode."; - Debug.WriteLine(errorText); - Console.WriteLine(errorText); + _logger.LogError("Fire timeout: no recovery progress in {Timeout}. Setting error mode.", _fireTimeout); _smoker.SetMode(SmokerMode.Error); } } @@ -256,21 +292,21 @@ internal void Tick() // debounce window before declaring it unhealthy. if (_belowCheckSince == null) { - _belowCheckSince = _now(); + _belowCheckSince = _timeProvider.GetTimestamp(); } - if (_now() - _belowCheckSince >= _fireCheckDebounce) + if (_timeProvider.GetElapsedTime(_belowCheckSince.Value) >= _fireCheckDebounce) { // Sustained decline — declare unhealthy and light the igniter // immediately so the recovery feed has an ignition source. _fireCheck = true; - _fireCheckTime = _now(); + _fireCheckTimestamp = _timeProvider.GetTimestamp(); _recoveryHigh = grillTemp; if (!_igniter.IsOn) { _igniter.On(); _ignitionTemp = Math.Max(150, checkTemp); - _igniterOnTime = _now(); + _igniterOnTimestamp = _timeProvider.GetTimestamp(); } } } diff --git a/Inferno.Api/Services/Smoker.cs b/Inferno.Api/Services/Smoker.cs index 939437e..db3b4e9 100644 --- a/Inferno.Api/Services/Smoker.cs +++ b/Inferno.Api/Services/Smoker.cs @@ -1,9 +1,9 @@ -using System.Diagnostics; using Inferno.Api.Interfaces; using Inferno.Common.Interfaces; using Inferno.Common.Models; using Inferno.Api.Pid; using Inferno.Common.Extensions; +using Microsoft.Extensions.Logging; namespace Inferno.Api.Services { @@ -15,6 +15,11 @@ public class Smoker : ISmoker, IDisposable IRelayDevice _igniter; IRtdArray _rtdArray; IDisplay _display; + readonly ILogger _logger; + // Monotonic clock for durations (shutdown cooldown), plus wall time for the + // status timestamps. Injected so a Pi's NTP step can't corrupt elapsed-time + // measurements and so tests can drive time deterministically. + readonly TimeProvider _timeProvider; int _setPoint; /// @@ -47,7 +52,7 @@ public class Smoker : ISmoker, IDisposable /// The PID determines a period of time to run the auger as a percentage of this time. /// Also used in Sear mode to determine how long to run the auger when the grill is too hot. /// - TimeSpan _holdCycle = TimeSpan.FromSeconds(10); + TimeSpan _holdCycle = TimeSpan.FromSeconds(20); // Per-mode token: cancelled by SetMode to interrupt the running mode's delay. // Guarded by _ctsLock so SetMode's Cancel() can never race ModeLoop's Dispose(). @@ -57,7 +62,10 @@ public class Smoker : ISmoker, IDisposable readonly CancellationTokenSource _lifetimeCts = new(); SmokerPid _pid; DateTime _lastModeChange; - + // Monotonic timestamp of the last mode change, used for the shutdown-cooldown + // duration so a wall-clock step can't cut the cooldown short or hang it. + long _lastModeChangeTimestamp; + /// /// Maximum value for the PID output. This is the maximum amount of the "hold" cycle time that the auger will run. /// @@ -98,23 +106,28 @@ public Smoker(IRelayDevice auger, IRelayDevice blower, IRelayDevice igniter, IRtdArray rtdArray, - IDisplay display) + IDisplay display, + ILoggerFactory loggerFactory, + TimeProvider? timeProvider = null) { _auger = auger; _blower = blower; _igniter = igniter; _rtdArray = rtdArray; _display = display; + _logger = loggerFactory.CreateLogger(); + _timeProvider = timeProvider ?? TimeProvider.System; _mode = SmokerMode.Ready; _setPoint = _minSetPoint; - _lastModeChange = DateTime.Now; + _lastModeChange = _timeProvider.GetLocalNow().DateTime; + _lastModeChangeTimestamp = _timeProvider.GetTimestamp(); PValue = 2; - _pid = new SmokerPid(60.0, 180.0, 45.0); + _pid = new SmokerPid(60.0, 180.0, 45.0, _timeProvider, loggerFactory.CreateLogger()); - _displayUpdater = new DisplayUpdater(this, _display); - _fireMinder = new FireMinder(this, _igniter); + _displayUpdater = new DisplayUpdater(this, _display, loggerFactory.CreateLogger()); + _fireMinder = new FireMinder(this, _igniter, _timeProvider, logger: loggerFactory.CreateLogger()); _preheatMonitor = new PreheatMonitor(); _modeLoopTask = ModeLoop(); _preheatLoopTask = PreheatLoop(); @@ -166,14 +179,14 @@ public SmokerStatus Status SetPoint = _setPoint, PValue = _pValue, ModeTime = _lastModeChange, - CurrentTime = DateTime.Now + CurrentTime = _timeProvider.GetLocalNow().DateTime }; } } public bool SetMode(SmokerMode newMode) { - Debug.WriteLine($"Setting mode {newMode}."); + _logger.LogInformation("Setting mode {NewMode}.", newMode); SmokerMode currentMode = _mode; @@ -221,7 +234,8 @@ public bool SetMode(SmokerMode newMode) } _mode = newMode; - _lastModeChange = DateTime.Now; + _lastModeChange = _timeProvider.GetLocalNow().DateTime; + _lastModeChangeTimestamp = _timeProvider.GetTimestamp(); // Interrupt the running mode's in-flight delay. ModeLoop owns disposal of // the token (under the same lock), so cancelling here is always safe. lock (_ctsLock) @@ -239,7 +253,7 @@ public bool SetMode(SmokerMode newMode) /// private async Task ModeLoop() { - Debug.WriteLine("Starting mode thread."); + _logger.LogDebug("Starting mode loop."); while (!_lifetimeCts.IsCancellationRequested) { // Fresh per-mode token, linked to the lifetime token so Dispose() also @@ -280,9 +294,11 @@ private async Task ModeLoop() } catch (Exception ex) { - string errorText = $"{DateTime.Now} Mode loop exception! {ex} {ex.StackTrace}"; - Console.WriteLine(errorText); - Debug.WriteLine(errorText); + _logger.LogError(ex, "Mode loop exception in {Mode} mode.", _mode); + // Back off briefly so a persistently-throwing mode method can't + // spin the loop at 100% CPU. + try { await Task.Delay(TimeSpan.FromSeconds(1), _lifetimeCts.Token); } + catch (OperationCanceledException) { break; } } } @@ -310,7 +326,7 @@ private async Task PreheatLoop() } catch (Exception ex) { - Debug.WriteLine($"{DateTime.Now} Preheat loop exception! {ex.Message}"); + _logger.LogError(ex, "Preheat loop exception."); } } } @@ -342,7 +358,7 @@ private async Task Smoke() await RunAuger(TimeSpan.FromSeconds(15), waitTime); if (_cts.IsCancellationRequested) { - Debug.WriteLine("Smoke mode cancelled."); + _logger.LogDebug("Smoke mode cancelled."); } } @@ -370,28 +386,28 @@ private async Task Hold() if (_igniter.IsOn && !_fireMinder.IsFireStarted) { - Debug.WriteLine("Hold: Igniter is on during startup. Diverting to SMOKE mode."); + _logger.LogDebug("Hold: Igniter is on during startup. Diverting to Smoke mode."); await Smoke(); return; } if (_setPoint == _maxSetPoint && _rtdArray.GrillTemp < _setPoint) { - Debug.WriteLine("Hold: Max setting. Skipping the PID, just running the auger."); + _logger.LogDebug("Hold: Max setting. Skipping the PID, running the auger continuously."); await RunAuger(); return; } if (_pid.SetPoint != _setPoint) { - Debug.WriteLine($"PID setpoint: {_pid.SetPoint}. Actual Setpoint: {SetPoint}. Updating."); + _logger.LogDebug("Updating PID setpoint from {PidSetPoint} to {SetPoint}.", _pid.SetPoint, SetPoint); _pid.SetPoint = _setPoint; } double u = _pid.GetControlVariable(_rtdArray.GrillTemp).Clamp(_uMin, _uMax); if(double.IsNaN(u)) { - Debug.WriteLine($"Hold: PID returned NaN. Setting u to {_uMin}."); + _logger.LogWarning("Hold: PID returned NaN. Falling back to minimum duty {UMin}.", _uMin); u = _uMin; } @@ -409,16 +425,17 @@ private async Task Hold() private async Task RunAuger(TimeSpan RunTime, TimeSpan WaitTime) { - Debug.WriteLine($"Auger running: {RunTime.Seconds} seconds."); + _logger.LogTrace("Auger running for {RunSeconds:F0}s, waiting {WaitSeconds:F0}s.", + RunTime.TotalSeconds, WaitTime.TotalSeconds); // Run the auger _auger.On(); try { await Task.Delay(RunTime, _cts.Token); } - catch (TaskCanceledException ex) + catch (TaskCanceledException) { - Debug.WriteLine($"{ex} Cancelled while auger running."); + _logger.LogTrace("Cancelled while auger running."); return; } @@ -427,9 +444,9 @@ private async Task RunAuger(TimeSpan RunTime, TimeSpan WaitTime) { await Task.Delay(WaitTime, _cts.Token); } - catch (TaskCanceledException ex) + catch (TaskCanceledException) { - Debug.WriteLine($"{ex} Cancelled while auger waiting."); + _logger.LogTrace("Cancelled while auger waiting."); } } @@ -441,9 +458,9 @@ private async Task RunAuger() { await Task.Delay(_holdCycle, _cts.Token); } - catch (TaskCanceledException ex) + catch (TaskCanceledException) { - Debug.WriteLine($"{ex} Running auger cancelled."); + _logger.LogTrace("Continuous auger run cancelled."); } } @@ -456,7 +473,7 @@ private async Task RunAuger() private async Task RecoveryFeed() { _blower.On(); - Debug.WriteLine("Recovery feed: aggressive auger to rebuild the fire."); + _logger.LogDebug("Recovery feed: aggressive auger to rebuild the fire."); await RunAuger(_recoveryFeedRunTime, _recoveryFeedWaitTime); } @@ -468,7 +485,7 @@ private async Task RecoveryFeed() private async Task MaintenanceFeed() { _blower.On(); - Debug.WriteLine("Maintenance feed: lid open, sustaining the fire."); + _logger.LogDebug("Maintenance feed: lid open, sustaining the fire."); await RunAuger(_maintenanceFeedRunTime, _maintenanceFeedWaitTime); } @@ -492,9 +509,16 @@ private async Task Sear() return; } + // Combustion air for the main sear path. The maintenance/recovery feeds + // above turn the blower on themselves; every other mode enables it before + // feeding, and Sear must too — otherwise a Sear entered from a cold blower + // (e.g. straight after Ready with a still-warm firepot) would feed the + // auger with no air, smoldering fuel in the tube. + _blower.On(); + if (_igniter.IsOn && !_fireMinder.IsFireStarted) { - Debug.WriteLine("Sear: Igniter is on during startup. Diverting to SMOKE mode."); + _logger.LogDebug("Sear: Igniter is on during startup. Diverting to Smoke mode."); await Smoke(); return; } @@ -502,7 +526,8 @@ private async Task Sear() int establishTemp = _fireMinder.InitialIgnitionTemp + _searEstablishMargin; if (_rtdArray.GrillTemp < establishTemp) { - Debug.WriteLine($"Sear: Grill temp {_rtdArray.GrillTemp} below establish temp {establishTemp} (ignition {_fireMinder.InitialIgnitionTemp} + {_searEstablishMargin}). Diverting to SMOKE to establish fire."); + _logger.LogDebug("Sear: Grill temp {GrillTemp} below establish temp {EstablishTemp} (ignition {IgnitionTemp} + {Margin}). Diverting to Smoke to establish fire.", + _rtdArray.GrillTemp, establishTemp, _fireMinder.InitialIgnitionTemp, _searEstablishMargin); await Smoke(); return; } @@ -513,7 +538,7 @@ private async Task Sear() } else { - Debug.WriteLine($"Sear: Over max grill temp. Running minimum auger time."); + _logger.LogDebug("Sear: Over max grill temp. Running minimum auger time."); var runTime = _holdCycle * _uMin; await RunAuger(runTime, _holdCycle - runTime); } @@ -529,7 +554,7 @@ private async Task Shutdown() _igniter.Off(); try { - if (DateTime.Now - _lastModeChange < _shutdownBlowerTimeout) + if (_timeProvider.GetElapsedTime(_lastModeChangeTimestamp) < _shutdownBlowerTimeout) { await Task.Delay(TimeSpan.FromSeconds(1), _cts.Token); } @@ -538,9 +563,9 @@ private async Task Shutdown() SetMode(SmokerMode.Ready); } } - catch (TaskCanceledException ex) + catch (TaskCanceledException) { - Debug.WriteLine($"{ex} Shutdown mode cancelled."); + _logger.LogTrace("Shutdown mode cancelled."); } } diff --git a/Inferno.Tests/FireMinderTests.cs b/Inferno.Tests/FireMinderTests.cs index 41fa360..211da03 100644 --- a/Inferno.Tests/FireMinderTests.cs +++ b/Inferno.Tests/FireMinderTests.cs @@ -2,6 +2,7 @@ using Inferno.Api.Services; using Inferno.Common.Interfaces; using Inferno.Common.Models; +using Microsoft.Extensions.Time.Testing; namespace Inferno.Tests; @@ -34,30 +35,23 @@ public bool SetMode(SmokerMode mode) } } - /// Mutable clock so tests can advance time between Tick() calls. - private sealed class TestClock - { - public DateTime Now = new DateTime(2026, 1, 1, 12, 0, 0); - public void Advance(TimeSpan t) => Now += t; - } - private static void SetGrill(FakeSmoker smoker, double temp) => smoker.Temps = new Temps { GrillTemp = temp, ProbeTemp = temp }; /// /// Builds a FireMinder that does NOT auto-run its loop, drives it to an - /// "established healthy fire" state (Hold @ 225, check temp = 195), and returns + /// "established healthy fire" state (Hold @ 225, check temp = 187), and returns /// the pieces so the test can manipulate temp/clock and call Tick() directly. /// - private static (FireMinder fm, FakeSmoker smoker, FakeRelay igniter, TestClock clock) EstablishedFire() + private static (FireMinder fm, FakeSmoker smoker, FakeRelay igniter, FakeTimeProvider clock) EstablishedFire() { var smoker = new FakeSmoker { Mode = SmokerMode.Hold, SetPoint = 225 }; var igniter = new FakeRelay(); - var clock = new TestClock(); - var fm = new FireMinder(smoker, igniter, () => clock.Now, autoStart: false); + var clock = new FakeTimeProvider(); + var fm = new FireMinder(smoker, igniter, clock, autoStart: false); fm.ResetFireStatus(); - // Two ticks above the check temp (195) proves the fire: first sets + // Two ticks above the check temp (187) proves the fire: first sets // _fireStarted, second clears _initialIgnition. SetGrill(smoker, 200); fm.Tick(); @@ -78,8 +72,8 @@ public void SlowColdStart_KeepsClimbing_DoesNotErrorBeforeIgnition() // instead of killing a fire that's plainly catching. var smoker = new FakeSmoker { Mode = SmokerMode.Hold, SetPoint = 250 }; var igniter = new FakeRelay(); - var clock = new TestClock(); - var fm = new FireMinder(smoker, igniter, () => clock.Now, autoStart: false); + var clock = new FakeTimeProvider(); + var fm = new FireMinder(smoker, igniter, clock, autoStart: false); fm.ResetFireStatus(); SetGrill(smoker, 75); @@ -115,8 +109,8 @@ public void ColdStart_NoProgress_StillTimesOutToError() // never triggers, so the fixed igniter timeout still gives up. var smoker = new FakeSmoker { Mode = SmokerMode.Hold, SetPoint = 250 }; var igniter = new FakeRelay(); - var clock = new TestClock(); - var fm = new FireMinder(smoker, igniter, () => clock.Now, autoStart: false); + var clock = new FakeTimeProvider(); + var fm = new FireMinder(smoker, igniter, clock, autoStart: false); fm.ResetFireStatus(); SetGrill(smoker, 75); @@ -144,6 +138,8 @@ public void GetFireCheckTemp_SmokeMode_Returns140() [Theory] [InlineData(225)] [InlineData(300)] + [InlineData(359)] + [InlineData(360)] [InlineData(400)] public void GetFireCheckTemp_HoldMode_ReturnsExpected(int setPoint) { @@ -151,10 +147,25 @@ public void GetFireCheckTemp_HoldMode_ReturnsExpected(int setPoint) var igniter = new FakeRelay(); var fm = new FireMinder(smoker, igniter, autoStart: false); - int expected = setPoint - (setPoint / 180 * 30); + // 5/6 of the setpoint (a 30F margin at the 180F floor), as a smooth curve. + int expected = (int)(setPoint * (150.0 / 180.0)); Assert.Equal(expected, fm.GetFireCheckTemp()); } + [Fact] + public void GetFireCheckTemp_HoldMode_HasNoCliffAtSetpoint360() + { + // Regression guard: the old integer `SetPoint / 180` made this a step function + // with a ~30F jump between setpoint 359 and 360. The proportional formula must + // stay continuous there. + var igniter = new FakeRelay(); + var below = new FireMinder(new FakeSmoker { Mode = SmokerMode.Hold, SetPoint = 359 }, igniter, autoStart: false); + var at = new FireMinder(new FakeSmoker { Mode = SmokerMode.Hold, SetPoint = 360 }, igniter, autoStart: false); + + Assert.True(Math.Abs(at.GetFireCheckTemp() - below.GetFireCheckTemp()) <= 2, + $"Expected a smooth threshold across setpoint 360, got {below.GetFireCheckTemp()} → {at.GetFireCheckTemp()}"); + } + [Fact] public void InitialState_FireNotStarted() { @@ -201,8 +212,8 @@ public void ColdStart_CapturesInitialIgnitionTempAtCatch() { var smoker = new FakeSmoker { Mode = SmokerMode.Sear, SetPoint = 400 }; var igniter = new FakeRelay(); - var clock = new TestClock(); - var fm = new FireMinder(smoker, igniter, () => clock.Now, autoStart: false); + var clock = new FakeTimeProvider(); + var fm = new FireMinder(smoker, igniter, clock, autoStart: false); fm.ResetFireStatus(); SetGrill(smoker, 75); @@ -225,7 +236,7 @@ public void InitialIgnitionTemp_UnchangedByRecoveryRelight() Assert.Equal(150, fm.InitialIgnitionTemp); // Trip recovery: the relight raises the internal ignition threshold to the - // fire-check temp (195), but the initial-catch anchor must stay put so Sear's + // fire-check temp (187), but the initial-catch anchor must stay put so Sear's // establish gate doesn't drift upward after a recovery. SetGrill(smoker, 180); fm.Tick(); @@ -241,7 +252,7 @@ public void BriefDip_RecoversBeforeDebounce_DoesNotTrip() { var (fm, smoker, igniter, clock) = EstablishedFire(); - // Dip below check temp (195), but recover before the 45s debounce elapses. + // Dip below check temp (187), but recover before the 45s debounce elapses. SetGrill(smoker, 180); fm.Tick(); Assert.True(fm.IsFireHealthy); // not declared unhealthy yet @@ -261,7 +272,7 @@ public void SustainedDecline_TripsAfterDebounce_AndLightsIgniterImmediately() { var (fm, smoker, igniter, clock) = EstablishedFire(); - SetGrill(smoker, 180); // below check temp (195) + SetGrill(smoker, 180); // below check temp (187) fm.Tick(); Assert.True(fm.IsFireHealthy); // debounce not yet satisfied Assert.False(igniter.IsOn); @@ -317,7 +328,7 @@ public void SlowlyClimbingFire_DoesNotError_ThenRecovers() { var (fm, smoker, igniter, clock) = EstablishedFire(); - // Drop well below check temp (195) and trip recovery. + // Drop well below check temp (187) and trip recovery. SetGrill(smoker, 160); fm.Tick(); clock.Advance(TimeSpan.FromSeconds(46)); @@ -325,9 +336,9 @@ public void SlowlyClimbingFire_DoesNotError_ThenRecovers() Assert.True(fm.IsReigniting); // Climb slowly: +6F every 3.5 min, staying below the check temp. Total elapsed - // (~17 min) far exceeds the 10 min fire/igniter timeouts, but each step is + // (~14 min) far exceeds the 10 min fire/igniter timeouts, but each step is // upward progress so the give-up clocks keep resetting. - foreach (var temp in new double[] { 166, 172, 178, 184, 190 }) + foreach (var temp in new double[] { 166, 172, 178, 184 }) { clock.Advance(TimeSpan.FromSeconds(210)); SetGrill(smoker, temp); @@ -409,7 +420,7 @@ public void LidOpen_SuppressesFireHealth_NoTripNoIgniter() fm.Tick(); Assert.True(fm.IsLidOpen); - // Even though temp (165) is below the check temp (195), and time passes, + // Even though temp (165) is below the check temp (187), and time passes, // the fire is NOT declared unhealthy and the igniter stays off. clock.Advance(TimeSpan.FromSeconds(60)); fm.Tick(); @@ -419,4 +430,43 @@ public void LidOpen_SuppressesFireHealth_NoTripNoIgniter() Assert.False(igniter.IsOn); Assert.False(fm.IsReigniting); } + + [Fact] + public void SensorFault_SustainedInvalidGrill_FailsSafeToError() + { + var (fm, smoker, igniter, clock) = EstablishedFire(); + + // The grill sensor drops out — the Smoker surfaces -1. A sustained fault must + // fail safe to Error rather than driving the aggressive recovery feed off a + // garbage temperature (the old behavior: -1 read as a dying fire → reignite). + for (int i = 0; i < 5; i++) // SensorFaultTicks + { + Assert.NotEqual(SmokerMode.Error, smoker.Mode); + SetGrill(smoker, -1); + fm.Tick(); + } + + Assert.Equal(SmokerMode.Error, smoker.Mode); + Assert.False(igniter.IsOn); + Assert.False(fm.IsReigniting); + } + + [Fact] + public void SensorFault_BriefInvalidBurst_DoesNotTrip() + { + var (fm, smoker, igniter, clock) = EstablishedFire(); + + // A short burst of invalid readings (below the fault threshold) followed by a + // good one: the counter resets and the cook continues untouched. + SetGrill(smoker, -1); + fm.Tick(); + SetGrill(smoker, -1); + fm.Tick(); + SetGrill(smoker, 200); + fm.Tick(); + + Assert.NotEqual(SmokerMode.Error, smoker.Mode); + Assert.True(fm.IsFireHealthy); + Assert.False(igniter.IsOn); + } } diff --git a/Inferno.Tests/Inferno.Tests.csproj b/Inferno.Tests/Inferno.Tests.csproj index ebbfeb5..c9f40da 100644 --- a/Inferno.Tests/Inferno.Tests.csproj +++ b/Inferno.Tests/Inferno.Tests.csproj @@ -9,6 +9,7 @@ +