From 1c15ff5911889291fa443aeb0e7917dca2fa71b5 Mon Sep 17 00:00:00 2001 From: Nathan Coad Date: Thu, 19 Feb 2026 12:36:52 +1100 Subject: [PATCH] Add read-only mode support and enhance logging throughout the application --- Dockerfile | 1 + README.md | 27 +++++++++ cmd/invertergui/config.go | 5 +- cmd/invertergui/main.go | 37 ++++++++++++ mk2core/core.go | 7 +++ mk2driver/mk2.go | 120 ++++++++++++++++++++++++++++++------- plugins/mqttclient/mqtt.go | 49 +++++++++++++++ plugins/webui/webgui.go | 68 ++++++++++++++++++--- 8 files changed, 281 insertions(+), 33 deletions(-) diff --git a/Dockerfile b/Dockerfile index e550201..305a9b6 100644 --- a/Dockerfile +++ b/Dockerfile @@ -9,6 +9,7 @@ FROM scratch # Group ID 20 is dialout, needed for tty read/write access USER 3000:20 +ENV READ_ONLY=false COPY --from=builder /build/invertergui /bin/ ENTRYPOINT [ "/bin/invertergui" ] EXPOSE 8080 diff --git a/README.md b/README.md index c20cbd0..010e2b7 100644 --- a/README.md +++ b/README.md @@ -31,6 +31,7 @@ Usage: Application Options: --address= The IP/DNS and port of the machine that the application is running on. (default: :8080) [$ADDRESS] + --read_only Disable all write operations and run in monitoring-only mode. [$READ_ONLY] --data.source= Set the source of data for the inverter gui. "serial", "tcp" or "mock" (default: serial) [$DATA_SOURCE] --data.host= Host to connect when source is set to tcp. (default: localhost:8139) [$DATA_HOST] --data.device= TTY device to use when source is set to serial. (default: /dev/ttyUSB0) [$DATA_DEVICE] @@ -54,6 +55,26 @@ Help Options: -h, --help Show this help message ``` +### Read-Only Mode + +Set `READ_ONLY=true` (or `--read_only`) to disable all write operations. +When read-only mode is enabled, the app still monitors and publishes telemetry, but it will not send commands to the Victron device. + +This affects: + +- MQTT command handling (`--mqtt.command_topic` commands are ignored) +- Web UI control actions (`POST /api/remote-panel/state` and `POST /api/remote-panel/standby`) + +Example `docker-compose.yml` snippet: + +```yaml +services: + invertergui: + image: registry.coadcorp.com/nathan/invertergui:latest + environment: + READ_ONLY: "true" +``` + ## Port 8080 The default HTTP server port is hosted on port 8080. This exposes the HTTP server that hosts the: @@ -315,6 +336,12 @@ The MQTT client will publish updates to the given broker at the set topic. --mqtt.password-file= Path to a file containing the MQTT password [$MQTT_PASSWORD_FILE] ``` +Related global option: + +```bash +--read_only Disable all write operations and run in monitoring-only mode. [$READ_ONLY] +``` + The MQTT client can be enabled by setting the environment variable `MQTT_ENABLED=true` or flag `--mqtt.enabled`. All MQTT configuration can be done via flags or as environment variables. The URI for the broker can be configured format should be `scheme://host:port`, where "scheme" is one of "tcp", "ssl", or "ws". diff --git a/cmd/invertergui/config.go b/cmd/invertergui/config.go index e6aed8b..7fe1778 100644 --- a/cmd/invertergui/config.go +++ b/cmd/invertergui/config.go @@ -9,8 +9,9 @@ import ( ) type config struct { - Address string `long:"address" env:"ADDRESS" default:":8080" description:"The IP/DNS and port of the machine that the application is running on."` - Data struct { + Address string `long:"address" env:"ADDRESS" default:":8080" description:"The IP/DNS and port of the machine that the application is running on."` + ReadOnly bool `long:"read_only" env:"READ_ONLY" description:"Disable all write operations and run in monitoring-only mode."` + Data struct { Source string `long:"data.source" env:"DATA_SOURCE" default:"serial" description:"Set the source of data for the inverter gui. \"serial\", \"tcp\" or \"mock\""` Host string `long:"data.host" env:"DATA_HOST" default:"localhost:8139" description:"Host to connect when source is set to tcp."` Device string `long:"data.device" env:"DATA_DEVICE" default:"/dev/ttyUSB0" description:"TTY device to use when source is set to serial."` diff --git a/cmd/invertergui/main.go b/cmd/invertergui/main.go index 96da5e5..93e9923 100644 --- a/cmd/invertergui/main.go +++ b/cmd/invertergui/main.go @@ -55,6 +55,7 @@ var log = logrus.WithField("ctx", "inverter-gui") func main() { conf, err := parseConfig() if err != nil { + log.WithError(err).Error("Could not parse configuration") os.Exit(1) } log.Info("Starting invertergui") @@ -63,16 +64,33 @@ func main() { log.Fatalf("Could not parse log level: %v", err) } logrus.SetLevel(logLevel) + log.WithFields(logrus.Fields{ + "loglevel": conf.Loglevel, + "address": conf.Address, + "read_only": conf.ReadOnly, + "data_source": conf.Data.Source, + "data_host": conf.Data.Host, + "data_device": conf.Data.Device, + "cli_enabled": conf.Cli.Enabled, + "mqtt_enabled": conf.MQTT.Enabled, + "mqtt_broker": conf.MQTT.Broker, + "mqtt_topic": conf.MQTT.Topic, + "mqtt_command_topic": conf.MQTT.CommandTopic, + "mqtt_status_topic": conf.MQTT.StatusTopic, + "mqtt_ha_enabled": conf.MQTT.HA.Enabled, + }).Info("Configuration loaded") mk2, err := getMk2Device(conf.Data.Source, conf.Data.Host, conf.Data.Device) if err != nil { log.Fatalf("Could not open data source: %v", err) } defer mk2.Close() + log.Info("MK2 device connection established") core := mk2core.NewCore(mk2) if conf.Cli.Enabled { + log.Info("CLI plugin enabled") cli.NewCli(core.NewSubscription()) } @@ -80,21 +98,35 @@ func main() { var writer mk2driver.SettingsWriter if w, ok := mk2.(mk2driver.SettingsWriter); ok { writer = w + log.Info("MK2 data source supports settings writes") + } else { + log.Warn("MK2 data source does not support settings writes") + } + if conf.ReadOnly { + if writer != nil { + log.Warn("READ_ONLY enabled; disabling all write operations") + } else { + log.Info("READ_ONLY enabled") + } + writer = nil } gui := webui.NewWebGui(core.NewSubscription(), writer) http.Handle("/", static.New()) http.Handle("/ws", http.HandlerFunc(gui.ServeHub)) http.Handle("/api/remote-panel/state", http.HandlerFunc(gui.ServeRemotePanelState)) http.Handle("/api/remote-panel/standby", http.HandlerFunc(gui.ServeRemotePanelStandby)) + log.Info("Web UI routes registered") // Munin mu := munin.NewMunin(core.NewSubscription()) http.Handle("/munin", http.HandlerFunc(mu.ServeMuninHTTP)) http.Handle("/muninconfig", http.HandlerFunc(mu.ServeMuninConfigHTTP)) + log.Info("Munin routes registered") // Prometheus prometheus.NewPrometheus(core.NewSubscription()) http.Handle("/metrics", promhttp.Handler()) + log.Info("Prometheus route registered") // MQTT if conf.MQTT.Enabled { @@ -119,6 +151,7 @@ func main() { if err := mqttclient.New(core.NewSubscription(), writer, mqttConf); err != nil { log.Fatalf("Could not setup MQTT client: %v", err) } + log.Info("MQTT client initialized") } log.Infof("Invertergui web server starting on: %v", conf.Address) @@ -134,12 +167,14 @@ func getMk2Device(source, ip, dev string) (mk2driver.Mk2, error) { switch source { case "serial": + log.WithField("device", dev).Info("Opening serial MK2 source") serialConfig := &serial.Config{Name: dev, Baud: 2400} p, err = serial.OpenPort(serialConfig) if err != nil { return nil, err } case "tcp": + log.WithField("host", ip).Info("Opening TCP MK2 source") tcpAddr, err = net.ResolveTCPAddr("tcp", ip) if err != nil { return nil, err @@ -149,6 +184,7 @@ func getMk2Device(source, ip, dev string) (mk2driver.Mk2, error) { return nil, err } case "mock": + log.Info("Using mock MK2 data source") return mk2driver.NewMk2Mock(), nil default: return nil, fmt.Errorf("Invalid source selection: %v\nUse \"serial\", \"tcp\" or \"mock\"", source) @@ -158,6 +194,7 @@ func getMk2Device(source, ip, dev string) (mk2driver.Mk2, error) { if err != nil { return nil, err } + log.WithField("source", source).Info("MK2 connection ready") return mk2, nil } diff --git a/mk2core/core.go b/mk2core/core.go index e126455..85247b7 100644 --- a/mk2core/core.go +++ b/mk2core/core.go @@ -2,8 +2,11 @@ package mk2core import ( "git.coadcorp.com/nathan/invertergui/mk2driver" + "github.com/sirupsen/logrus" ) +var log = logrus.WithField("ctx", "inverter-gui-core") + type Core struct { mk2driver.Mk2 plugins map[*subscription]bool @@ -16,6 +19,7 @@ func NewCore(m mk2driver.Mk2) *Core { register: make(chan *subscription, 255), plugins: map[*subscription]bool{}, } + log.Info("Core initialized") go core.run() return core } @@ -25,6 +29,7 @@ func (c *Core) NewSubscription() mk2driver.Mk2 { send: make(chan *mk2driver.Mk2Info), } c.register <- sub + log.Debug("New plugin subscription registered") return sub } @@ -33,11 +38,13 @@ func (c *Core) run() { select { case r := <-c.register: c.plugins[r] = true + log.WithField("subscribers", len(c.plugins)).Debug("Subscription added") case e := <-c.C(): for plugin := range c.plugins { select { case plugin.send <- e: default: + log.WithField("subscribers", len(c.plugins)).Warn("Dropping update for a slow subscriber") } } } diff --git a/mk2driver/mk2.go b/mk2driver/mk2.go index 6e9b0a1..dda76bb 100644 --- a/mk2driver/mk2.go +++ b/mk2driver/mk2.go @@ -11,6 +11,8 @@ import ( "github.com/sirupsen/logrus" ) +var mk2log = logrus.WithField("ctx", "inverter-gui-mk2driver") + type scaling struct { scale float64 offset float64 @@ -122,6 +124,7 @@ func NewMk2Connection(dev io.ReadWriter) (Mk2, error) { mk2.run = make(chan struct{}) mk2.infochan = make(chan *Mk2Info) mk2.wg.Add(1) + mk2log.Info("MK2 connection initialized") go mk2.frameLocker() return mk2, nil } @@ -163,7 +166,7 @@ func (m *mk2Ser) frameLocker() { } else { if checkChecksum(frameLength, tmp, frame[:frameLengthOffset]) { m.frameLock = true - logrus.Info("Locked") + mk2log.Info("Frame lock acquired") } } } @@ -174,8 +177,10 @@ func (m *mk2Ser) frameLocker() { // Close Mk2 func (m *mk2Ser) Close() { + mk2log.Info("Closing MK2 connection") close(m.run) m.wg.Wait() + mk2log.Info("MK2 connection closed") } func (m *mk2Ser) C() chan *Mk2Info { @@ -183,11 +188,31 @@ func (m *mk2Ser) C() chan *Mk2Info { } func (m *mk2Ser) WriteRAMVar(id uint16, value int16) error { - return m.writeByID(commandWriteRAMVar, commandWriteRAMResponse, id, value) + mk2log.WithFields(logrus.Fields{ + "id": id, + "value": value, + }).Info("WriteRAMVar requested") + err := m.writeByID(commandWriteRAMVar, commandWriteRAMResponse, id, value) + if err != nil { + mk2log.WithError(err).WithField("id", id).Error("WriteRAMVar failed") + return err + } + mk2log.WithField("id", id).Info("WriteRAMVar applied") + return nil } func (m *mk2Ser) WriteSetting(id uint16, value int16) error { - return m.writeByID(commandWriteSetting, commandWriteSettingResponse, id, value) + mk2log.WithFields(logrus.Fields{ + "id": id, + "value": value, + }).Info("WriteSetting requested") + err := m.writeByID(commandWriteSetting, commandWriteSettingResponse, id, value) + if err != nil { + mk2log.WithError(err).WithField("id", id).Error("WriteSetting failed") + return err + } + mk2log.WithField("id", id).Info("WriteSetting applied") + return nil } func (m *mk2Ser) SetPanelState(switchState PanelSwitchState, currentLimitA *float64) error { @@ -203,6 +228,12 @@ func (m *mk2Ser) SetPanelState(switchState PanelSwitchState, currentLimitA *floa m.commandMu.Lock() defer m.commandMu.Unlock() + logEntry := mk2log.WithField("switch_state", switchState) + if currentLimitA != nil { + logEntry = logEntry.WithField("current_limit_a", *currentLimitA) + } + logEntry.Info("SetPanelState requested") + m.clearStateResponses() m.sendCommandLocked([]byte{ stateFrame, @@ -213,7 +244,13 @@ func (m *mk2Ser) SetPanelState(switchState PanelSwitchState, currentLimitA *floa panelStateVariant2Flags, }) - return m.waitForStateResponse() + err = m.waitForStateResponse() + if err != nil { + logEntry.WithError(err).Error("SetPanelState failed") + return err + } + logEntry.Info("SetPanelState acknowledged") + return nil } func (m *mk2Ser) SetStandby(enabled bool) error { @@ -224,6 +261,8 @@ func (m *mk2Ser) SetStandby(enabled bool) error { m.commandMu.Lock() defer m.commandMu.Unlock() + logEntry := mk2log.WithField("standby_enabled", enabled) + logEntry.Info("SetStandby requested") m.clearInterfaceResponses() m.sendCommandLocked([]byte{ @@ -231,7 +270,13 @@ func (m *mk2Ser) SetStandby(enabled bool) error { lineState, }) - return m.waitForInterfaceResponse(enabled) + err := m.waitForInterfaceResponse(enabled) + if err != nil { + logEntry.WithError(err).Error("SetStandby failed") + return err + } + logEntry.Info("SetStandby acknowledged") + return nil } func validPanelSwitchState(switchState PanelSwitchState) bool { @@ -261,6 +306,12 @@ func encodePanelCurrentLimit(currentLimitA *float64) (uint16, error) { func (m *mk2Ser) writeByID(selectCommand, expectedResponse byte, id uint16, value int16) error { m.commandMu.Lock() defer m.commandMu.Unlock() + mk2log.WithFields(logrus.Fields{ + "select_command": fmt.Sprintf("0x%02x", selectCommand), + "expected_response": fmt.Sprintf("0x%02x", expectedResponse), + "id": id, + "value": value, + }).Debug("Issuing write-by-id command") m.clearWriteResponses() @@ -303,6 +354,10 @@ func (m *mk2Ser) waitForWriteResponse(expectedResponse byte) error { select { case response := <-m.writeAck: + mk2log.WithFields(logrus.Fields{ + "expected_response": fmt.Sprintf("0x%02x", expectedResponse), + "received_response": fmt.Sprintf("0x%02x", response), + }).Debug("Received write acknowledgement") switch response { case expectedResponse: return nil @@ -314,6 +369,7 @@ func (m *mk2Ser) waitForWriteResponse(expectedResponse byte) error { return fmt.Errorf("unexpected write response 0x%02x", response) } case <-time.After(writeResponseTimeout): + mk2log.WithField("expected_response", fmt.Sprintf("0x%02x", expectedResponse)).Error("Timed out waiting for write acknowledgement") return fmt.Errorf("timed out waiting for write response after %s", writeResponseTimeout) } } @@ -350,8 +406,10 @@ func (m *mk2Ser) waitForStateResponse() error { select { case <-m.stateAck: + mk2log.Debug("Received panel state acknowledgement") return nil case <-time.After(writeResponseTimeout): + mk2log.Error("Timed out waiting for panel state acknowledgement") return fmt.Errorf("timed out waiting for panel state response after %s", writeResponseTimeout) } } @@ -389,11 +447,17 @@ func (m *mk2Ser) waitForInterfaceResponse(expectedStandby bool) error { select { case lineState := <-m.ifaceAck: standbyEnabled := lineState&interfaceStandbyFlag != 0 + mk2log.WithFields(logrus.Fields{ + "line_state": fmt.Sprintf("0x%02x", lineState), + "expected_standby": expectedStandby, + "actual_standby": standbyEnabled, + }).Debug("Received standby interface acknowledgement") if standbyEnabled != expectedStandby { return fmt.Errorf("unexpected standby line state 0x%02x", lineState) } return nil case <-time.After(writeResponseTimeout): + mk2log.WithField("expected_standby", expectedStandby).Error("Timed out waiting for standby acknowledgement") return fmt.Errorf("timed out waiting for standby response after %s", writeResponseTimeout) } } @@ -421,7 +485,7 @@ func (m *mk2Ser) readByte() byte { // Adds error to error slice. func (m *mk2Ser) addError(err error) { - logrus.Errorf("Mk2 serial slice error: %q", err.Error()) + mk2log.Errorf("Mk2 serial slice error: %q", err.Error()) if m.info.Errors == nil { m.info.Errors = make([]error, 0) } @@ -432,16 +496,27 @@ func (m *mk2Ser) addError(err error) { // Updates report. func (m *mk2Ser) updateReport() { m.info.Timestamp = time.Now() + mk2log.WithFields(logrus.Fields{ + "in_voltage": m.info.InVoltage, + "in_current": m.info.InCurrent, + "out_voltage": m.info.OutVoltage, + "out_current": m.info.OutCurrent, + "bat_voltage": m.info.BatVoltage, + "bat_current": m.info.BatCurrent, + "charge_state": m.info.ChargeState, + "valid": m.info.Valid, + }).Debug("Publishing MK2 status update") select { case m.infochan <- m.info: default: + mk2log.Warn("Dropping MK2 status update; consumer channel is full") } m.info = &Mk2Info{} } // Checks for valid frame and chooses decoding. func (m *mk2Ser) handleFrame(l byte, frame []byte) { - logrus.Debugf("[handleFrame] frame %#v", frame) + mk2log.Debugf("[handleFrame] frame %#v", frame) if checkChecksum(l, frame[0], frame[1:]) { switch frame[0] { case bootupFrameHeader: @@ -465,13 +540,13 @@ func (m *mk2Ser) handleFrame(l byte, frame []byte) { case commandWriteRAMResponse, commandWriteSettingResponse, commandUnsupportedResponse, commandWriteNotAllowedResponse: m.pushWriteResponse(frame[2]) default: - logrus.Warnf("[handleFrame] invalid winmonFrame %v", frame[2:]) + mk2log.Warnf("[handleFrame] invalid winmonFrame %v", frame[2:]) } case ledFrame: m.ledDecode(frame[2:]) default: - logrus.Warnf("[handleFrame] invalid frameHeader %v", frame[1]) + mk2log.Warnf("[handleFrame] invalid frameHeader %v", frame[1]) } case infoFrameHeader: @@ -481,13 +556,13 @@ func (m *mk2Ser) handleFrame(l byte, frame []byte) { case acL1InfoFrame: m.acDecode(frame[1:]) default: - logrus.Warnf("[handleFrame] invalid infoFrameHeader %v", frame[5]) + mk2log.Warnf("[handleFrame] invalid infoFrameHeader %v", frame[5]) } default: - logrus.Warnf("[handleFrame] Invalid frame %v", frame[0]) + mk2log.Warnf("[handleFrame] Invalid frame %v", frame[0]) } } else { - logrus.Errorf("[handleFrame] Invalid incoming frame checksum: %x", frame) + mk2log.Errorf("[handleFrame] Invalid incoming frame checksum: %x", frame) m.frameLock = false } } @@ -520,10 +595,10 @@ func int16Abs(in int16) uint16 { // Decode the scale factor frame. func (m *mk2Ser) scaleDecode(frame []byte) { tmp := scaling{} - logrus.Debugf("Scale frame(%d): 0x%x", len(frame), frame) + mk2log.Debugf("Scale frame(%d): 0x%x", len(frame), frame) if len(frame) < 6 { tmp.supported = false - logrus.Warnf("Skiping scaling factors for: %d", m.scaleCount) + mk2log.Warnf("Skiping scaling factors for: %d", m.scaleCount) } else { tmp.supported = true var scl int16 @@ -546,19 +621,19 @@ func (m *mk2Ser) scaleDecode(frame []byte) { tmp.scale = float64(scale) } } - logrus.Debugf("scalecount %v: %#v \n", m.scaleCount, tmp) + mk2log.Debugf("scalecount %v: %#v \n", m.scaleCount, tmp) m.scales = append(m.scales, tmp) m.scaleCount++ if m.scaleCount < ramVarMaxOffset { m.reqScaleFactor(byte(m.scaleCount)) } else { - logrus.Info("Monitoring starting.") + mk2log.Info("Monitoring starting.") } } // Decode the version number func (m *mk2Ser) versionDecode(frame []byte) { - logrus.Debugf("versiondecode %v", frame) + mk2log.Debugf("versiondecode %v", frame) m.info.Version = 0 m.info.Valid = true for i := 0; i < 4; i++ { @@ -566,7 +641,7 @@ func (m *mk2Ser) versionDecode(frame []byte) { } if m.scaleCount < ramVarMaxOffset { - logrus.Info("Get scaling factors.") + mk2log.WithField("version", m.info.Version).Info("Get scaling factors") m.reqScaleFactor(byte(m.scaleCount)) } else { // Send DC status request @@ -623,7 +698,7 @@ func (m *mk2Ser) dcDecode(frame []byte) { m.info.BatCurrent = usedC - chargeC m.info.OutFrequency = m.calcFreq(frame[13], ramVarInverterPeriod) - logrus.Debugf("dcDecode %#v", m.info) + mk2log.Debugf("dcDecode %#v", m.info) // Send L1 status request cmd := make([]byte, 2) @@ -640,7 +715,7 @@ func (m *mk2Ser) acDecode(frame []byte) { m.info.OutCurrent = m.applyScale(getSigned(frame[11:13]), ramVarIInverter) m.info.InFrequency = m.calcFreq(frame[13], ramVarMainPeriod) - logrus.Debugf("acDecode %#v", m.info) + mk2log.Debugf("acDecode %#v", m.info) // Send status request cmd := make([]byte, 1) @@ -658,7 +733,7 @@ func (m *mk2Ser) calcFreq(data byte, scaleIndex int) float64 { // Decode charge state of battery. func (m *mk2Ser) stateDecode(frame []byte) { m.info.ChargeState = m.applyScaleAndSign(frame[1:3], ramVarChargeState) - logrus.Debugf("battery state decode %#v", m.info) + mk2log.Debugf("battery state decode %#v", m.info) m.updateReport() } @@ -711,9 +786,10 @@ func (m *mk2Ser) sendCommandLocked(data []byte) { } dataOut[l+2] = cr - logrus.Debugf("sendCommand %#v", dataOut) + mk2log.Debugf("sendCommand %#v", dataOut) _, err := m.p.Write(dataOut) if err != nil { + mk2log.WithError(err).Error("Failed to send MK2 command") m.addError(fmt.Errorf("Write error: %v", err)) } } diff --git a/plugins/mqttclient/mqtt.go b/plugins/mqttclient/mqtt.go index 63d6561..f44a3de 100644 --- a/plugins/mqttclient/mqtt.go +++ b/plugins/mqttclient/mqtt.go @@ -99,6 +99,17 @@ type panelStateCache struct { // New creates an MQTT client that publishes MK2 updates and optionally handles setting write commands. func New(mk2 mk2driver.Mk2, writer mk2driver.SettingsWriter, config Config) error { + log.WithFields(logrus.Fields{ + "broker": config.Broker, + "client_id": config.ClientID, + "topic": config.Topic, + "command_topic": config.CommandTopic, + "status_topic": config.StatusTopic, + "ha_enabled": config.HomeAssistant.Enabled, + "ha_node_id": config.HomeAssistant.NodeID, + "ha_device_name": config.HomeAssistant.DeviceName, + }).Info("Initializing MQTT client") + c := mqtt.NewClient(getOpts(config)) if token := c.Connect(); token.Wait() && token.Error() != nil { return token.Error() @@ -135,14 +146,18 @@ func New(mk2 mk2driver.Mk2, writer mk2driver.SettingsWriter, config Config) erro go func() { for e := range mk2.C() { if e == nil || !e.Valid { + log.Debug("Skipping invalid/nil MK2 event for MQTT publish") continue } if err := publishJSON(c, config.Topic, e, 0, false); err != nil { log.Errorf("Could not publish update to MQTT topic %q: %v", config.Topic, err) + } else { + log.WithField("topic", config.Topic).Debug("Published MK2 update to MQTT") } } }() + log.Info("MQTT client setup complete") return nil } @@ -152,9 +167,14 @@ func subscribeHAPanelModeState(client mqtt.Client, config Config, cache *panelSt } stateTopic := haPanelSwitchStateTopic(config) + log.WithField("topic", stateTopic).Info("Subscribing to Home Assistant mode state topic for panel cache") t := client.Subscribe(stateTopic, 1, func(_ mqtt.Client, msg mqtt.Message) { switchState, switchName, err := normalizePanelSwitch(string(msg.Payload())) if err != nil { + log.WithFields(logrus.Fields{ + "topic": msg.Topic(), + "payload": string(msg.Payload()), + }).WithError(err).Warn("Ignoring invalid Home Assistant mode state payload") return } cache.remember(writeCommand{ @@ -163,6 +183,10 @@ func subscribeHAPanelModeState(client mqtt.Client, config Config, cache *panelSt SwitchState: switchState, SwitchName: switchName, }) + log.WithFields(logrus.Fields{ + "topic": msg.Topic(), + "switch_name": switchName, + }).Debug("Updated panel mode cache from Home Assistant state topic") }) t.Wait() return t.Error() @@ -174,6 +198,11 @@ func commandHandler(client mqtt.Client, writer mk2driver.SettingsWriter, config } return func(_ mqtt.Client, msg mqtt.Message) { + log.WithFields(logrus.Fields{ + "topic": msg.Topic(), + "payload": string(msg.Payload()), + }).Debug("Received MQTT command message") + cmd, err := decodeWriteCommand(msg.Payload()) if err != nil { log.Errorf("Invalid MQTT write command payload from topic %q: %v", msg.Topic(), err) @@ -247,6 +276,7 @@ func (c *panelStateCache) resolvePanelCommand(cmd writeCommand) (writeCommand, e cmd.HasSwitch = true cmd.SwitchName = c.switchName cmd.SwitchState = c.switchState + log.WithField("switch", cmd.SwitchName).Debug("Resolved panel command switch from cache") return cmd, nil } @@ -260,6 +290,7 @@ func (c *panelStateCache) remember(cmd writeCommand) { c.switchName = cmd.SwitchName c.switchState = cmd.SwitchState c.mu.Unlock() + log.WithField("switch", cmd.SwitchName).Debug("Remembered panel switch state in cache") } func decodeWriteCommand(payload []byte) (writeCommand, error) { @@ -465,6 +496,7 @@ func decodeStandbyValue(msg writeCommandPayload) (bool, error) { func publishWriteStatus(client mqtt.Client, topic string, status writeStatus) { if topic == "" { + log.Debug("Skipping write status publish; status topic is empty") return } if err := publishJSON(client, topic, status, 1, false); err != nil { @@ -479,6 +511,11 @@ func publishHADiscovery(client mqtt.Client, config Config) error { for _, def := range definitions { topic := fmt.Sprintf("%s/%s/%s/%s/config", prefix, def.Component, nodeID, def.ObjectID) + log.WithFields(logrus.Fields{ + "topic": topic, + "component": def.Component, + "object_id": def.ObjectID, + }).Debug("Publishing Home Assistant discovery definition") if err := publishJSON(client, topic, def.Config, 1, true); err != nil { return fmt.Errorf("could not publish discovery for %s/%s: %w", def.Component, def.ObjectID, err) } @@ -665,6 +702,12 @@ func publishJSON(client mqtt.Client, topic string, payload any, qos byte, retain if t.Error() != nil { return t.Error() } + log.WithFields(logrus.Fields{ + "topic": topic, + "qos": qos, + "retained": retained, + "bytes": len(data), + }).Debug("Published JSON message") return nil } @@ -679,6 +722,12 @@ func publishString(client mqtt.Client, topic, payload string, qos byte, retained if t.Error() != nil { return t.Error() } + log.WithFields(logrus.Fields{ + "topic": topic, + "qos": qos, + "retained": retained, + "payload": payload, + }).Debug("Published string message") return nil } diff --git a/plugins/webui/webgui.go b/plugins/webui/webgui.go index 0377d6b..1c0f202 100644 --- a/plugins/webui/webgui.go +++ b/plugins/webui/webgui.go @@ -85,6 +85,7 @@ func NewWebGui(source mk2driver.Mk2, writer mk2driver.SettingsWriter) *WebGui { Mode: modeUnknown, }, } + log.WithField("remote_writable", writer != nil).Info("Web UI initialized") w.wg.Add(1) go w.dataPoll() return w @@ -138,50 +139,77 @@ type setRemotePanelStandbyRequest struct { } func (w *WebGui) ServeHub(rw http.ResponseWriter, r *http.Request) { + log.WithFields(logrus.Fields{ + "remote": r.RemoteAddr, + "path": r.URL.Path, + }).Debug("WebSocket hub request") w.hub.ServeHTTP(rw, r) } func (w *WebGui) ServeRemotePanelState(rw http.ResponseWriter, r *http.Request) { + log.WithFields(logrus.Fields{ + "method": r.Method, + "path": r.URL.Path, + "remote": r.RemoteAddr, + }).Debug("Remote panel state API request") + switch r.Method { case http.MethodGet: writeJSON(rw, http.StatusOK, w.getRemotePanelState()) case http.MethodPost: w.handleSetRemotePanelState(rw, r) default: + log.WithField("method", r.Method).Warn("Remote panel state API received unsupported method") http.Error(rw, "method not allowed", http.StatusMethodNotAllowed) } } func (w *WebGui) ServeRemotePanelStandby(rw http.ResponseWriter, r *http.Request) { + log.WithFields(logrus.Fields{ + "method": r.Method, + "path": r.URL.Path, + "remote": r.RemoteAddr, + }).Debug("Remote panel standby API request") + switch r.Method { case http.MethodGet: writeJSON(rw, http.StatusOK, w.getRemotePanelState()) case http.MethodPost: w.handleSetRemotePanelStandby(rw, r) default: + log.WithField("method", r.Method).Warn("Remote panel standby API received unsupported method") http.Error(rw, "method not allowed", http.StatusMethodNotAllowed) } } func (w *WebGui) handleSetRemotePanelState(rw http.ResponseWriter, r *http.Request) { if w.writer == nil { + log.Warn("Remote panel state write requested, but writer is unavailable") http.Error(rw, "remote control is not supported by this data source", http.StatusNotImplemented) return } req := setRemotePanelStateRequest{} if err := decodeJSONBody(r, &req); err != nil { + log.WithError(err).Warn("Invalid remote panel state request body") http.Error(rw, err.Error(), http.StatusBadRequest) return } + logEntry := log.WithField("mode", req.Mode) + if req.CurrentLimit != nil { + logEntry = logEntry.WithField("current_limit_a", *req.CurrentLimit) + } + logEntry.Info("Applying remote panel state from API") switchState, normalizedMode, err := parsePanelMode(req.Mode) if err != nil { + logEntry.WithError(err).Warn("Unsupported remote panel mode") http.Error(rw, err.Error(), http.StatusBadRequest) return } if err := w.writer.SetPanelState(switchState, req.CurrentLimit); err != nil { + logEntry.WithError(err).Error("Failed to apply remote panel state") w.updateRemotePanelState(func(state *remotePanelState) { state.LastCommand = "set_remote_panel_state" state.LastError = err.Error() @@ -196,22 +224,27 @@ func (w *WebGui) handleSetRemotePanelState(rw http.ResponseWriter, r *http.Reque state.LastCommand = "set_remote_panel_state" state.LastError = "" }) + logEntry.WithField("normalized_mode", normalizedMode).Info("Remote panel state applied") writeJSON(rw, http.StatusOK, w.getRemotePanelState()) } func (w *WebGui) handleSetRemotePanelStandby(rw http.ResponseWriter, r *http.Request) { if w.writer == nil { + log.Warn("Remote panel standby write requested, but writer is unavailable") http.Error(rw, "remote control is not supported by this data source", http.StatusNotImplemented) return } req := setRemotePanelStandbyRequest{} if err := decodeJSONBody(r, &req); err != nil { + log.WithError(err).Warn("Invalid remote panel standby request body") http.Error(rw, err.Error(), http.StatusBadRequest) return } + log.WithField("standby", req.Standby).Info("Applying standby state from API") if err := w.writer.SetStandby(req.Standby); err != nil { + log.WithError(err).WithField("standby", req.Standby).Error("Failed to apply standby state") w.updateRemotePanelState(func(state *remotePanelState) { state.LastCommand = "set_remote_panel_standby" state.LastError = err.Error() @@ -225,6 +258,7 @@ func (w *WebGui) handleSetRemotePanelStandby(rw http.ResponseWriter, r *http.Req state.LastCommand = "set_remote_panel_standby" state.LastError = "" }) + log.WithField("standby", req.Standby).Info("Standby state applied") writeJSON(rw, http.StatusOK, w.getRemotePanelState()) } @@ -301,23 +335,32 @@ func buildTemplateInput(status *mk2driver.Mk2Info) *templateInput { } func (w *WebGui) Stop() { + log.Info("Stopping Web UI polling") close(w.stopChan) w.wg.Wait() + log.Info("Web UI polling stopped") } func (w *WebGui) dataPoll() { for { select { case s := <-w.C(): - if s.Valid { - payload := buildTemplateInput(s) - w.stateMu.Lock() - payload.RemotePanel = w.remote - w.latest = payload - w.stateMu.Unlock() - if err := w.hub.Broadcast(payload); err != nil { - log.Errorf("Could not send update to clients: %v", err) - } + if s == nil { + log.Debug("Skipping nil MK2 update in Web UI poller") + continue + } + if !s.Valid { + log.WithField("errors", len(s.Errors)).Debug("Skipping invalid MK2 update in Web UI poller") + continue + } + + payload := buildTemplateInput(s) + w.stateMu.Lock() + payload.RemotePanel = w.remote + w.latest = payload + w.stateMu.Unlock() + if err := w.hub.Broadcast(payload); err != nil { + log.Errorf("Could not send update to clients: %v", err) } case <-w.stopChan: w.wg.Done() @@ -336,6 +379,13 @@ func (w *WebGui) updateRemotePanelState(update func(state *remotePanelState)) { w.stateMu.Lock() update(&w.remote) w.remote.LastUpdated = time.Now().UTC().Format(time.RFC3339) + log.WithFields(logrus.Fields{ + "mode": w.remote.Mode, + "has_limit": w.remote.CurrentLimit != nil, + "has_standby": w.remote.Standby != nil, + "last_command": w.remote.LastCommand, + "last_error": w.remote.LastError, + }).Debug("Updated remote panel state cache") snapshot := w.snapshotLocked() w.stateMu.Unlock()