SM-877 Improve edge logs logic for Fingerprint - set max retries for …

…fingerprint (#78)

* wip

* implement improved persistence and edge logs logic

* remove unused code, start updating tests

* remove un-needed test

* update tests

internal/fingerprint.go

@@ -1,9 +1,8 @@
 package internal
 
 import (
+	"context"
 	"fmt"
-	"time"
-
 	"github.com/DIMO-Network/edge-network/internal/models"
 
 	"github.com/rs/zerolog"
@@ -19,8 +18,9 @@ import (
 )
 
 type FingerprintRunner interface {
-	Fingerprint() error
 	FingerprintSimple(powerStatus api.PowerStatusResponse) error
+	CurrentFailureCount() int
+	IncrementFailuresReached() int
 }
 
 type fingerprintRunner struct {
@@ -29,57 +29,76 @@ type fingerprintRunner struct {
 	dataSender    network.DataSender
 	templateStore loggers.TemplateStore
 	logger        zerolog.Logger
+	// state tracking
+	failureCount int
+	// allTimeFailureCount is loaded from disk from last boot - used to determine edge-logging need. Increments by 1 per boot cycle even if retried many times in one boot
+	allTimeFailureCount int
+	// pastVINQueryName is loaded from disk from last boot - used to speedup VIN request if we already know the method that worked last
+	pastVINQueryName *string
 }
 
 func NewFingerprintRunner(unitID uuid.UUID, vinLog loggers.VINLogger, dataSender network.DataSender, templateStore loggers.TemplateStore, logger zerolog.Logger) FingerprintRunner {
-	return &fingerprintRunner{unitID: unitID, vinLog: vinLog, dataSender: dataSender, templateStore: templateStore, logger: logger}
+	fpr := &fingerprintRunner{unitID: unitID, vinLog: vinLog, dataSender: dataSender, templateStore: templateStore, logger: logger}
+	fpr.failureCount = 0
+	fpr.allTimeFailureCount = 0
+
+	pastVINInfo, err := fpr.templateStore.ReadVINConfig()
+	if err != nil {
+		fpr.logger.Info().Msgf("could not read settings, continuing: %s", err)
+	} else {
+		fpr.allTimeFailureCount = pastVINInfo.VINLoggerFailedAttempts
+
+		if pastVINInfo.VINQueryName != "" {
+			fpr.pastVINQueryName = &pastVINInfo.VINQueryName
+			fpr.logger.Debug().Msgf("found previous VIN query name: %s", pastVINInfo.VINQueryName)
+		}
+	}
+	return fpr
+}
+
+func (ls *fingerprintRunner) CurrentFailureCount() int {
+	return ls.failureCount
 }
 
-const maxFailureAttempts = 5
+// IncrementFailuresReached update the templateStore VIN info config with in incremented failure count and writes it to disk
+func (ls *fingerprintRunner) IncrementFailuresReached() int {
+	config := &models.VINLoggerSettings{
+		VINLoggerVersion:        loggers.VINLoggerVersion,
+		VINLoggerFailedAttempts: ls.allTimeFailureCount + 1,
+	}
+	writeErr := ls.templateStore.WriteVINConfig(*config)
+	if writeErr != nil {
+		ls.logger.Err(writeErr).Send()
+	}
+	return config.VINLoggerFailedAttempts
+}
 
 // FingerprintSimple does no voltage checks, just scans for the VIN, saves query used, and sends cloud event signed.
+// if failure getting vin, logs to console and updates the failure count on disk - wonder if this is necessary
 func (ls *fingerprintRunner) FingerprintSimple(powerStatus api.PowerStatusResponse) error {
 	// no voltage check, assumption is this has already been checked before here.
-	config, err := ls.templateStore.ReadVINConfig()
-	if err != nil {
-		ls.logger.Info().Msgf("could not read settings, continuing: %s", err)
-	}
-	var vqn *string
-	if config != nil {
-		vqn = &config.VINQueryName
-		ls.logger.Info().Msgf("found VIN query name: %s", *vqn)
-	}
 	// scan for VIN
 	vinLogger := LoggerProperties{
 		SignalName: "vin",
 		Interval:   0,
 		ScanFunc:   ls.vinLog.GetVIN,
 	}
 	// assumption here is that the vin query name, if set, will work on this car. If the device has been moved to a different car without pairing again, this won't work
-	vinResp, err := vinLogger.ScanFunc(ls.unitID, vqn)
+	vinResp, err := vinLogger.ScanFunc(ls.unitID, ls.pastVINQueryName)
 	if err != nil {
-		if config == nil {
-			config = &models.VINLoggerSettings{}
-		}
-		ls.logger.Err(err).Msgf("failed to scan for vin. fail count: %d", config.VINLoggerFailedAttempts)
-		// update local settings to increment fail count
-		config.VINLoggerVersion = loggers.VINLoggerVersion
-		config.VINLoggerFailedAttempts++
-		writeErr := ls.templateStore.WriteVINConfig(*config)
-		if writeErr != nil {
-			ls.logger.Err(writeErr).Send()
-		}
-
-		_ = ls.dataSender.SendErrorPayload(errors.Wrap(err, "failed to get VIN from vinLogger"), &powerStatus)
+		ls.failureCount++
+		// just return the error here and let the caller save to disk + log to edge etc
+		return errors.Wrap(err, fmt.Sprintf("failed to scan for vin. fail count since boot: %d", ls.failureCount))
 	}
-	// save vin query name in settings if not set
-	if config == nil || config.VINQueryName == "" {
-		config = &models.VINLoggerSettings{VINQueryName: vinResp.QueryName, VIN: vinResp.VIN}
+	// save vin query name in settings & report to edge logs if not set - normally this should only happen once with a given car.
+	if ls.pastVINQueryName == nil {
+		config := &models.VINLoggerSettings{VINQueryName: vinResp.QueryName, VIN: vinResp.VIN}
 		err := ls.templateStore.WriteVINConfig(*config)
 		if err != nil {
 			ls.logger.Err(err).Send()
 			_ = ls.dataSender.SendErrorPayload(errors.Wrap(err, "failed to write vinLogger settings"), &powerStatus)
 		}
+		ls.logger.Info().Ctx(context.WithValue(context.Background(), LogToMqtt, "true")).Msgf("succesfully obtained VIN via fingerprint")
 	}
 
 	data := models.FingerprintData{
@@ -101,141 +120,6 @@ func (ls *fingerprintRunner) FingerprintSimple(powerStatus api.PowerStatusRespon
 	return nil
 }
 
-// Fingerprint checks if ok to start scanning the vehicle and then tries to get the VIN & Protocol via various methods.
-// Runs only once when successful.  Checks for saved VIN query from previous run.
-func (ls *fingerprintRunner) Fingerprint() error {
-	// check if ok to start making obd calls etc
-	ls.logger.Info().Msg("fingerprint starting, checking if can start scanning")
-	ok, status, err := ls.isOkToScan()
-	if err != nil {
-		_ = ls.dataSender.SendErrorPayload(errors.Wrap(err, "checks to start loggers failed"), &status)
-		return errors.Wrap(err, "checks to start loggers failed, no action")
-	}
-	if !ok {
-		e := fmt.Errorf("checks to start loggers failed but no errors reported")
-		_ = ls.dataSender.SendErrorPayload(e, &status)
-		return e
-	}
-	ls.logger.Info().Msg("loggers: checks passed to start scanning")
-	// read any existing settings
-	config, err := ls.templateStore.ReadVINConfig()
-	if err != nil {
-		ls.logger.Info().Msgf("could not read settings, continuing: %s", err)
-	}
-	var vqn *string
-	if config != nil {
-		vqn = &config.VINQueryName
-		// check if we do not want to continue scanning VIN for this car - currently determines if we run any loggers (but do note some cars won't respond VIN but yes on most OBD2 stds)
-		if config.VINLoggerVersion == loggers.VINLoggerVersion { // if vin vinLogger improves, basically ignore failed attempts as maybe we decoded it.
-			if config.VINLoggerFailedAttempts >= maxFailureAttempts {
-				if config.VINQueryName != "" {
-					// this would be really weird and needs to be addressed
-					_ = ls.dataSender.SendErrorPayload(fmt.Errorf("failed attempts exceeded but was previously able to get VIN with query: %s", config.VINQueryName), &status)
-				}
-				return fmt.Errorf("failed attempts for VIN vinLogger exceeded, not starting loggers")
-			}
-		}
-	}
-	// scan for VIN
-	vinLogger := LoggerProperties{
-		SignalName: "vin",
-		Interval:   0,
-		ScanFunc:   ls.vinLog.GetVIN,
-	}
-	vinResp, err := vinLogger.ScanFunc(ls.unitID, vqn)
-	if err != nil {
-		if config == nil {
-			config = &models.VINLoggerSettings{}
-		}
-		ls.logger.Err(err).Msgf("failed to scan for vin. fail count: %d", config.VINLoggerFailedAttempts)
-		// update local settings to increment fail count
-		config.VINLoggerVersion = loggers.VINLoggerVersion
-		config.VINLoggerFailedAttempts++
-		writeErr := ls.templateStore.WriteVINConfig(*config)
-		if writeErr != nil {
-			ls.logger.Err(writeErr).Send()
-		}
-		_ = ls.dataSender.SendErrorPayload(errors.Wrap(err, "failed to get VIN from vinLogger"), &status)
-
-		return err
-	} else if config == nil {
-		// save vin query name in settings if not set
-		config = &models.VINLoggerSettings{VINQueryName: vinResp.QueryName, VIN: vinResp.VIN}
-		err := ls.templateStore.WriteVINConfig(*config)
-		if err != nil {
-			ls.logger.Err(err).Send()
-			_ = ls.dataSender.SendErrorPayload(errors.Wrap(err, "failed to write vinLogger settings"), &status)
-		}
-	}
-
-	data := models.FingerprintData{
-		Vin:      vinResp.VIN,
-		Protocol: vinResp.Protocol,
-	}
-	data.Device.RpiUptimeSecs = status.Rpi.Uptime.Seconds
-	data.Device.BatteryVoltage = status.Stn.Battery.Voltage
-
-	err = ls.dataSender.SendFingerprintData(data)
-	if err != nil {
-		ls.logger.Err(err).Send()
-	}
-
-	return nil
-}
-
-// once logger starts, for signals we want to grab continuosly eg odometer, we need more sophisticated logger pausing: from shaolin-
-//Yeah so the device itself will still try and talk to the canbus with PIDS when the vehicle is off and then these german cars see this and think someone is trying to break into the car so it sets off the car alarm
-//So what we did is we disabled the obd manager so it doesnt ask for PIDs anymore so you dont get obd data
-//so what this solution does, is while the car is on and in motion, the obd manager is enabled, will send PIDS and grab data, then once the vehicle stops, the manager turns off
-//its a more advanced obd logger pausing
-
-// isOkToScan checks if the power status and other heuristics to determine if ok to start Open CAN scanning and PID requests. Blocking.
-func (ls *fingerprintRunner) isOkToScan() (result bool, status api.PowerStatusResponse, err error) {
-	const maxTries = 100
-	const voltageMin = 13.2 // todo this should come from device config but have defaults
-	tries := 0
-	status, httpError := commands.GetPowerStatus(ls.unitID)
-	for httpError != nil {
-		if tries > maxTries {
-			return false, status, fmt.Errorf("loggers: unable to get power.status after %d tries with error %s", maxTries, httpError.Error())
-		}
-		status, httpError = commands.GetPowerStatus(ls.unitID)
-		tries++
-		time.Sleep(2 * time.Second)
-	}
-
-	ls.logger.Info().Msgf("loggers: Last Start Reason: %s - Voltage: %f", status.Spm.LastTrigger.Up, status.VoltageFound)
-	if status.Spm.LastTrigger.Up == "volt_change" || status.Spm.LastTrigger.Up == "volt_level" || status.Spm.LastTrigger.Up == "stn" || status.Spm.LastTrigger.Up == "spm" {
-		if status.VoltageFound >= voltageMin {
-			// good to start scanning
-			result = true
-			return
-		}
-		// loop a few more times
-		tries = 0
-		for status.VoltageFound < voltageMin {
-			if tries > maxTries {
-				err = fmt.Errorf("loggers: did not reach a satisfactory voltage to start loggers: %f", status.Stn.Battery.Voltage)
-				ls.logger.Err(err).Send()
-				break
-			}
-			status, httpError = commands.GetPowerStatus(ls.unitID)
-			tries++
-			time.Sleep(2 * time.Second)
-		}
-		if httpError != nil {
-			err = httpError
-		}
-	} else {
-		return false, status,
-			fmt.Errorf("loggers: Spm.LastTrigger.Up value not expected so not starting logger: %s - Voltage: %f - required Voltage: %f",
-				status.Spm.LastTrigger.Up, status.VoltageFound, voltageMin)
-	}
-	// this may be an initial pair or something else so we don't wanna start loggers, just exit
-	result = false
-	return
-}
-
 type LoggerProperties struct {
 	// SignalName name of signal to be published over mqtt
 	SignalName string

internal/fingerprint_test.go

@@ -2,6 +2,7 @@ package internal
 
 import (
 	"fmt"
+	"github.com/DIMO-Network/edge-network/internal/api"
 	"net/http"
 	"os"
 	"testing"
@@ -37,6 +38,7 @@ func Test_fungerprintRunner_VINLoggers(t *testing.T) {
 		Timestamp().
 		Str("app", "edge-network").
 		Logger()
+	ts.EXPECT().ReadVINConfig().Times(1).Return(&models.VINLoggerSettings{VINQueryName: vinQueryName}, nil)
 
 	ls := NewFingerprintRunner(unitID, vl, ds, ts, logger)
 
@@ -49,11 +51,10 @@ func Test_fungerprintRunner_VINLoggers(t *testing.T) {
 	httpmock.RegisterResponder(http.MethodPost, autoPiBaseURL+ethPath,
 		httpmock.NewStringResponder(200, `{"value": "b794f5ea0ba39494ce839613fffba74279579268"}`))
 
-	ts.EXPECT().ReadVINConfig().Times(1).Return(&models.VINLoggerSettings{VINQueryName: vinQueryName}, nil)
 	vl.EXPECT().GetVIN(unitID, &vinQueryName).Times(1).Return(&loggers.VINResponse{VIN: vinDiesel, Protocol: "6", QueryName: vinQueryName}, nil)
 	ds.EXPECT().SendFingerprintData(gomock.Any()).Times(1).Return(nil)
 
-	err := ls.Fingerprint()
+	err := ls.FingerprintSimple(api.PowerStatusResponse{VoltageFound: 13.7})
 
 	assert.NoError(t, err)
 }
@@ -78,6 +79,7 @@ func Test_fingerprintRunner_VINLoggers_nilSettings(t *testing.T) {
 		Str("app", "edge-network").
 		Logger()
 
+	ts.EXPECT().ReadVINConfig().Times(1).Return(nil, fmt.Errorf("error reading file: open /tmp/logger-settings.json: no such file or directory"))
 	ls := NewFingerprintRunner(unitID, vl, ds, ts, logger)
 
 	// mock powerstatus resp
@@ -89,12 +91,13 @@ func Test_fingerprintRunner_VINLoggers_nilSettings(t *testing.T) {
 	httpmock.RegisterResponder(http.MethodPost, autoPiBaseURL+ethPath,
 		httpmock.NewStringResponder(200, `{"value": "b794f5ea0ba39494ce839613fffba74279579268"}`))
 
-	ts.EXPECT().ReadVINConfig().Times(1).Return(nil, fmt.Errorf("error reading file: open /tmp/logger-settings.json: no such file or directory"))
 	vl.EXPECT().GetVIN(unitID, nil).Times(1).Return(&loggers.VINResponse{VIN: vinDiesel, Protocol: "6", QueryName: vinQueryName}, nil)
 	ts.EXPECT().WriteVINConfig(models.VINLoggerSettings{VINQueryName: vinQueryName, VIN: vinDiesel}).Times(1).Return(nil)
 	ds.EXPECT().SendFingerprintData(gomock.Any()).Times(1).Return(nil)
 
-	err := ls.Fingerprint()
+	err := ls.FingerprintSimple(api.PowerStatusResponse{
+		VoltageFound: 13.5,
+	})
 
 	assert.NoError(t, err)
 }
@@ -118,6 +121,7 @@ func Test_fingerprintRunner_VINLoggers_noVINResponse(t *testing.T) {
 		Str("app", "edge-network").
 		Logger()
 
+	ts.EXPECT().ReadVINConfig().Times(1).Return(nil, fmt.Errorf("error reading file: open /tmp/logger-settings.json: no such file or directory"))
 	ls := NewFingerprintRunner(unitID, vl, ds, ts, logger)
 
 	// mock powerstatus resp
@@ -130,59 +134,10 @@ func Test_fingerprintRunner_VINLoggers_noVINResponse(t *testing.T) {
 		httpmock.NewStringResponder(200, `{"value": "b794f5ea0ba39494ce839613fffba74279579268"}`))
 
 	// nil settings, eg. first time it runs, incompatiible vehicle
-	ts.EXPECT().ReadVINConfig().Times(1).Return(nil, fmt.Errorf("error reading file: open /tmp/logger-settings.json: no such file or directory"))
 	noVinErr := fmt.Errorf("response contained an invalid vin")
 	vl.EXPECT().GetVIN(unitID, nil).Times(1).Return(nil, noVinErr)
-	ts.EXPECT().WriteVINConfig(models.VINLoggerSettings{
-		VINQueryName:            "",
-		VINLoggerVersion:        loggers.VINLoggerVersion,
-		VINLoggerFailedAttempts: 1,
-		VIN:                     "",
-	}).Return(nil)
-	ds.EXPECT().SendErrorPayload(gomock.Any(), gomock.Any()).Times(1).Return(nil)
 
-	err := ls.Fingerprint()
+	err := ls.FingerprintSimple(api.PowerStatusResponse{VoltageFound: 13.7})
 
 	assert.Error(t, err, "response contained an invalid vin")
 }
-
-func Test_fingerprintRunner_VINLoggers_noVINResponseAndAttemptsExceeded(t *testing.T) {
-	httpmock.Activate()
-	defer httpmock.DeactivateAndReset()
-	const autoPiBaseURL = "http://192.168.4.1:9000"
-	unitID := uuid.New()
-
-	mockCtrl := gomock.NewController(t)
-	defer mockCtrl.Finish()
-
-	vl := mock_loggers.NewMockVINLogger(mockCtrl)
-	ds := mock_network.NewMockDataSender(mockCtrl)
-	ts := mock_loggers.NewMockTemplateStore(mockCtrl)
-
-	logger := zerolog.New(os.Stdout).With().
-		Timestamp().
-		Str("app", "edge-network").
-		Logger()
-
-	ls := NewFingerprintRunner(unitID, vl, ds, ts, logger)
-
-	// mock powerstatus resp
-	psPath := fmt.Sprintf("/dongle/%s/execute_raw/", unitID)
-	httpmock.RegisterResponder(http.MethodPost, autoPiBaseURL+psPath,
-		httpmock.NewStringResponder(200, `{"spm": {"last_trigger": {"up": "volt_change"}, "battery": {"voltage": 13.3}}}`))
-	// mock eth addr
-	ethPath := fmt.Sprintf("/dongle/%s/execute_raw", unitID)
-	httpmock.RegisterResponder(http.MethodPost, autoPiBaseURL+ethPath,
-		httpmock.NewStringResponder(200, `{"value": "b794f5ea0ba39494ce839613fffba74279579268"}`))
-
-	// nil settings, eg. first time it runs, incompatiible vehicle
-	ts.EXPECT().ReadVINConfig().Times(1).Return(&models.VINLoggerSettings{
-		VINQueryName:            "",
-		VINLoggerVersion:        loggers.VINLoggerVersion,
-		VINLoggerFailedAttempts: 5,
-	}, nil)
-
-	err := ls.Fingerprint()
-
-	assert.Error(t, err)
-}

internal/loggers/dbc_formula_decoder_test.go

@@ -33,6 +33,8 @@ func TestExtractAndDecodeWithFormula(t *testing.T) {
 		{"7e803410581cccccccc", "5", "31|8@0+ (1,-40) [-40|215] \"degC\"", 89, "degC", ""},
 		{"7e803410585aaaaaaaa", "5", "31|8@0+ (1,-40) [-40|215] \"degC\"", 93, "degC", ""},
 		{"7e803410585aaaaaaaa", "05", "31|8@0+ (1,-40) [-40|215] \"degC\"", 93, "degC", ""}, // 0 padded pid
+		// mache odoemteter
+		{"7e80662dd01003f5acc", "dd01", "39|24@0+ (1,0) [0|2150000] \"km\"", 16218, "km", ""},
 	}
 
 	for _, test := range tests {