diff --git a/API Server/internal/plugins/builtin/ankersolix/cloudmqtt.go b/API Server/internal/plugins/builtin/ankersolix/cloudmqtt.go index 0a6b567..9c38568 100644 --- a/API Server/internal/plugins/builtin/ankersolix/cloudmqtt.go +++ b/API Server/internal/plugins/builtin/ankersolix/cloudmqtt.go @@ -44,11 +44,14 @@ import ( "crypto/x509" "encoding/base64" "encoding/binary" + "encoding/hex" "encoding/json" "errors" "fmt" + "log" "math/big" "net" + "os" "strings" "sync" "time" @@ -469,15 +472,46 @@ func (c *mqttConn) idleLoop() { } } +// mqttFrameLog writes a line for every inbound frame — the ones this package can +// read and, the whole point, the ones it cannot. Off unless ANKER_MQTT_FRAME_LOG +// is set on the server: it exists to put a name to a frame nobody has named yet +// (a card held against the reader, say, or one of the two types the map lists as +// unnamed), not to write a line per telemetry message on a running server. +var mqttFrameLog = os.Getenv("ANKER_MQTT_FRAME_LOG") != "" + +// frameLogLine is that line. The bytes are the part that matters — a frame this +// package drops is unreadable here but perfectly readable afterwards — so they +// are always in it, capped so one long frame cannot fill a log. +func frameLogLine(sn, topic string, data []byte, msgType string, values map[string]any, err error) string { + hexed := hex.EncodeToString(data) + if len(hexed) > 1024 { + hexed = hexed[:1024] + "..." + } + if err != nil { + return fmt.Sprintf("ANKER-MQTT FRAME sn=%s topic=%s len=%d unreadable=%q hex=%s", + sn, topic, len(data), err.Error(), hexed) + } + return fmt.Sprintf("ANKER-MQTT FRAME sn=%s topic=%s len=%d type=%s fields=%d hex=%s values=%v", + sn, topic, len(data), msgType, len(values), hexed, values) +} + // ingest decodes one inbound message and folds it into the sending charger's // state. Anything it cannot read is dropped: these frames come from a cloud // connection, and a malformed one must not be recorded as a reading. func (c *mqttConn) ingest(msg mqtt.Message) { sn, data, ok := parseEnvelope(msg) if !ok { + if mqttFrameLog { + log.Printf("ANKER-MQTT ENVELOPE topic=%s unreadable payload=%s", msg.Topic, msg.Payload) + } return } msgType, values, err := decodeFrame(data) + // Logged before the drop below, because the frames worth naming are exactly + // the ones this package throws away. + if mqttFrameLog { + log.Print(frameLogLine(sn, msg.Topic, data, msgType, values, err)) + } if err != nil || len(values) == 0 { return } diff --git a/API Server/internal/plugins/builtin/ankersolix/framelog_test.go b/API Server/internal/plugins/builtin/ankersolix/framelog_test.go new file mode 100644 index 0000000..d22d5d1 --- /dev/null +++ b/API Server/internal/plugins/builtin/ankersolix/framelog_test.go @@ -0,0 +1,36 @@ +package ankersolix + +import ( + "errors" + "strings" + "testing" +) + +// The frame nobody can read is the one worth logging, so its bytes have to be in +// the line — that is the whole of what a capture is. +func TestFrameLogLineCarriesTheBytes(t *testing.T) { + data := []byte{0xff, 0x09, 0x01, 0x02} + line := frameLogLine("EVSN1", "dt/app/A5191/EVSN1/x", data, "", nil, errors.New("bad marker")) + if !strings.Contains(line, "hex=ff090102") { + t.Errorf("unreadable frame: %q, want the bytes in it", line) + } + if !strings.Contains(line, "unreadable=") || !strings.Contains(line, "EVSN1") { + t.Errorf("unreadable frame: %q, want the reason and the serial", line) + } + + line = frameLogLine("EVSN1", "t", data, "0857", map[string]any{"a": 1}, nil) + if !strings.Contains(line, "type=0857") || !strings.Contains(line, "fields=1") { + t.Errorf("readable frame: %q, want its type and field count", line) + } +} + +// One long frame must not fill a log file. +func TestFrameLogLineCapsTheHex(t *testing.T) { + line := frameLogLine("EVSN1", "t", make([]byte, 4096), "0410", nil, nil) + if len(line) > 1400 { + t.Errorf("line is %d chars, want it capped", len(line)) + } + if !strings.Contains(line, "...") { + t.Error("a truncated frame should say so") + } +} diff --git a/Docker/.env.example b/Docker/.env.example index 99fecd8..f03c3fe 100644 --- a/Docker/.env.example +++ b/Docker/.env.example @@ -34,6 +34,15 @@ AUTH_USERS_COLLECTION=users # public wss:// base, or set OCPP_REQUIRE_TLS=false on a trusted network. OCPP_REQUIRE_TLS=true OCPP_PUBLIC_URL= + +# Diagnostic only. Set to 1 to log every frame the charger publishes over Anker's +# cloud broker — the ones DriverVault decodes and the ones it cannot, with their +# bytes. It is how an unnamed frame gets named: hold a control read open, do the +# thing in the Anker app, then read the frames back out of the container log. +# Leave blank on a normal stack; a triggered charger writes a line every few +# seconds. +ANKER_MQTT_FRAME_LOG= + # The charger can dial either door: the API Server port directly, or the Web # App port, whose BFF now proxies /ocpp/ through to it. The endpoint the panel # shows is the API Server port only when OCPP_PUBLIC_URL says so — left blank it diff --git a/Docker/.env.prod.example b/Docker/.env.prod.example index 1fb4a60..92c67a5 100644 --- a/Docker/.env.prod.example +++ b/Docker/.env.prod.example @@ -47,6 +47,15 @@ AUTH_USERS_COLLECTION=users # networks only. OCPP_REQUIRE_TLS=true OCPP_PUBLIC_URL= + +# Diagnostic only. Set to 1 to log every frame the charger publishes over Anker's +# cloud broker — the ones DriverVault decodes and the ones it cannot, with their +# bytes. It is how an unnamed frame gets named: hold a control read open, do the +# thing in the Anker app, then read the frames back out of the container log. +# Leave blank on a normal stack; a triggered charger writes a line every few +# seconds. +ANKER_MQTT_FRAME_LOG= + # The charger can dial either door: the API Server port directly, or the Web # App port, whose BFF now proxies /ocpp/ through to it. The endpoint the panel # shows is the API Server port only when OCPP_PUBLIC_URL says so — left blank it diff --git a/Docker/docker-compose.prod.yml b/Docker/docker-compose.prod.yml index 33f7d2e..e081be2 100644 --- a/Docker/docker-compose.prod.yml +++ b/Docker/docker-compose.prod.yml @@ -81,6 +81,13 @@ services: # reach this port; only drop OCPP_REQUIRE_TLS on a trusted network. OCPP_REQUIRE_TLS: "${OCPP_REQUIRE_TLS:-true}" OCPP_PUBLIC_URL: "${OCPP_PUBLIC_URL:-}" + # Diagnostic: set ANKER_MQTT_FRAME_LOG=1 in .env to log every frame the + # charger publishes over Anker's broker, decoded ones and unreadable ones + # alike, with their bytes. It is how a frame nobody has named gets named — + # do something in the Anker app while a control read holds the connection + # open, and read the frames back out of the log. Off by default: with it on + # a charger under a live trigger writes a line every few seconds. + ANKER_MQTT_FRAME_LOG: "${ANKER_MQTT_FRAME_LOG:-}" ports: # Localhost-only by default (the Web App reaches it over the internal # network). Set API_BIND=0.0.0.0 to expose the API panel — and the diff --git a/Docker/docker-compose.yml b/Docker/docker-compose.yml index d64fd9c..76e5833 100644 --- a/Docker/docker-compose.yml +++ b/Docker/docker-compose.yml @@ -74,6 +74,13 @@ services: # terminated in front of this stack or for local dev on a trusted network. OCPP_REQUIRE_TLS: "${OCPP_REQUIRE_TLS:-true}" OCPP_PUBLIC_URL: "${OCPP_PUBLIC_URL:-}" + # Diagnostic: set ANKER_MQTT_FRAME_LOG=1 in .env to log every frame the + # charger publishes over Anker's broker, decoded ones and unreadable ones + # alike, with their bytes. It is how a frame nobody has named gets named — + # do something in the Anker app while a control read holds the connection + # open, and read the frames back out of the log. Off by default: with it on + # a charger under a live trigger writes a line every few seconds. + ANKER_MQTT_FRAME_LOG: "${ANKER_MQTT_FRAME_LOG:-}" ports: # Optional direct access to the API Server (and its panel at /); the Web # App reaches it over the internal network, not this host port. Chargers