Add read-only mode support and enhance logging throughout the application

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))
 	}
 }