Stuck communication around CurrentDemandRes

[lewurm]

Today I had a rather long running session going on (see timestamps, ~157 minutes), and then it stopped:

[...]
[9420864ms] [EVSE] from 4 entering 4
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 38 18 18 18 00 84 00 C0
[SNIFFER] EXI from 49153 to 15118 (40bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 D1 40 0D 00 80 C2 38 08 02 05 08 62 10 08 0C 3C 80 80 A0 E1 2C 02 22 10 28 43 10 80
[9420896ms] [EVSE] In state WaitForFlexibleRequest, received (48bytes) = 01 FE 80 01 00 00 00 28 80 9A 02 00 40 80 C1 01 41 81 C2 10 D1 40 0D 00 80 C2 38 08 02 05 08 62 10 08 0C 3C 80 80 A0 E1 2C 02 22 10 28 43 10 80                                                                                                                                                    [9420899ms] [EVSE] {
"msgName": "CurrentDemandReq",
"info": "40 bytes to convert",
"error": "",
"result": "",
"schema": "DIN",
"g_errn": "0",
"header.SessionID": "0102030405060708",
"header.Notification_isUsed": "0",
"header.Signature_isUsed": "0",
"DC_EVStatus.EVReady": "1",
"DC_EVStatus.EVErrorCode": "0",
"DC_EVErrorCodeText": "NO_ERROR",
"DC_EVStatus.EVRESSSOC": "52",
"EVTargetCurrent.Multiplier": "-1",
"EVTargetCurrent.Value": "270",
"EVTargetCurrent.Unit": "A",
"EVMaximumVoltageLimit_isUsed": "1",
"EVMaximumVoltageLimit.Multiplier": "-1",
"EVMaximumVoltageLimit.Value": "4230",
"EVMaximumVoltageLimit.Unit": "V",
"EVMaximumCurrentLimit_isUsed": "1",
"EVMaximumCurrentLimit.Multiplier": "-1",
"EVMaximumCurrentLimit.Value": "370",
"EVMaximumCurrentLimit.Unit": "A",
"EVMaximumPowerLimit_isUsed": "1",
"EVMaximumPowerLimit.Multiplier": "2",
"EVMaximumPowerLimit.Value": "150",
"EVMaximumPowerLimit.Unit": "W",
"ChargingComplete": "0",
"EVTargetVoltage.Multiplier": "-1",
"EVTargetVoltage.Value": "4230",
"EVTargetVoltage.Unit": "V",
"debug": "Line9057Line9260Line436"
}
[9420900ms] [EVSE] EV wants EVTargetVoltage 423.0
Received SoC status from CurrentDemandReq.
    Current SoC 52%
    Full SoC -1%
    Energy capacity 27000 Wh
    Energy request -1 Wh
    EVCCID dc4427101615

[9420904ms] [EVSE] responding (36bytes) = 01 FE 80 01 00 00 00 1C 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0
[9420907ms] [EVSE] {
"msgName": "CurrentDemandRes",
"info": "28 bytes to convert",
"error": "",
"result": "",
"schema": "DIN",
"g_errn": "0",
"header.SessionID": "0102030405060708",
"header.Notification_isUsed": "0",
"header.Signature_isUsed": "0",
"ResponseCode": "OK",
"DC_EVSEStatus.EVSEIsolationStatus": "1",
"DC_EVSEStatus.EVSEIsolationStatus_isUsed": "1",
"DC_EVSEStatus.EVSEStatusCode": "1",
"EVSEStatusCode_text": "EVSE_Ready",
"DC_EVSEStatus.NotificationMaxDelay": "0",
"DC_EVSEStatus.EVSENotification": "0",
"EVSEPresentVoltage.Multiplier": "0",
"EVSEPresentVoltage.Value": "425",
"EVSEPresentVoltage.Unit": "V",
"EVSEPresentCurrent.Multiplier": "0",
"EVSEPresentCurrent.Value": "1",
"EVSEPresentCurrent.Unit": "A",
"EVSECurrentLimitAchieved": "1",
"EVSEVoltageLimitAchieved": "0",
"EVSEPowerLimitAchieved": "0",
"EVSEMaximumVoltageLimit.Multiplier": "0",
"EVSEMaximumVoltageLimit.Value": "0",
"EVSEMaximumVoltageLimit.Unit": "h",
"debug": "Line442"
}
[9420908ms] [EVSE] from 4 entering 4
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0
[9429055ms] [EVSE] from 4 entering 0
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0
[SNIFFER] EXI from 15118 to 49153 (28bytes) = 80 9A 02 00 40 80 C1 01 41 81 C2 10 E0 00 40 80 00 01 82 85 48 18 18 18 00 84 00 C0

Any idea what was happening? The car didn't give any more info.

From the log it's not clear which line caused the state change, so for next time I added this: https://gist.github.com/lewurm/209404e00059d18e6907302532b2edd3

[lewurm]

2024-12-11_190937_evse_tesla_model3_tcpdump.pcap.zip

[lewurm]

Looking at it in Wireshark shows a couple of TCP Retransmissions on the Raspberry side, and the car seems gone.

Actually... that might be related to #35 after all; I have another log where TCP retransmissions also happen, but the car ACKs it a few seconds (!) later, and then immediately closes the connection: 2024-12-10_195224_evse_tesla_model3_tcpdump.pcap.zip

So probably not much pyPLC can do about 😕