Stuck at step with testing exiConnector.py

[fluppie]

Hi, I'm following along the manual at https://github.com/uhi22/pyPLC/blob/master/doc/installation_on_raspberry.md

pi@rpievse:~/myprogs/pyPlc $ python exiConnector.py
Testing exiConnector...
Traceback (most recent call last):
  File "/home/pi/myprogs/pyPlc/exiConnector.py", line 317, in <module>
    testReadExiFromExiLogFile()
  File "/home/pi/myprogs/pyPlc/exiConnector.py", line 265, in testReadExiFromExiLogFile
    file1 = open('PevExiLog.txt', 'r')
FileNotFoundError: [Errno 2] No such file or directory: 'PevExiLog.txt'

pi@rpievse:~/myprogs/pyPlc $ sudo python exiConnector.py
Testing exiConnector...
Traceback (most recent call last):
  File "/home/pi/myprogs/pyPlc/exiConnector.py", line 317, in <module>
    testReadExiFromExiLogFile()
  File "/home/pi/myprogs/pyPlc/exiConnector.py", line 265, in testReadExiFromExiLogFile
    file1 = open('PevExiLog.txt', 'r')
FileNotFoundError: [Errno 2] No such file or directory: 'PevExiLog.txt'

I ignored it and continued steps, since this step worked for me:

cd $home/myprogs/OpenV2Gx/Release
    ./OpenV2G.exe DD809a0010d0400000c800410c8000
    ./OpenV2G.exe EDB_5555aaaa5555aaaa

seeing some data but seeing "[EVSE] re-initializing fsmEvse due to broken connection"

[182099ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[184888ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[187676ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[188353ms] received SLAC_PARAM.REQ
[addressManager] pev has MAC EC:65:CC:B6:85:DC
[188360ms] [EVSE] transmitting CM_SLAC_PARAM.CNF
[188615ms] received MNBC_SOUND.IND
[188620ms] received MNBC_SOUND.IND
[188708ms] received MNBC_SOUND.IND
[188710ms] received MNBC_SOUND.IND
[188713ms] received MNBC_SOUND.IND
[188716ms] received MNBC_SOUND.IND
[188802ms] received MNBC_SOUND.IND
[188805ms] received MNBC_SOUND.IND
[188808ms] received MNBC_SOUND.IND
[188895ms] received MNBC_SOUND.IND
[188897ms] [EVSE] transmitting ATTEN_CHAR.IND
[189742ms] received SLAC_MATCH.REQ
[189746ms] [EVSE] transmitting SLAC_MATCH.CNF
[190507ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[193296ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[addressManager] pev has IP fe80:0000:0000:0000:ee65:ccff:feb6:85dc
V2GTP (10bytes) = 01 FE 90 00 00 00 00 02 10 00
Ok, this was a valid SDP request. We are the SECC. Sending SDP response.
SDP payload (20bytes) = FE 80 00 00 00 00 00 00 05 A3 B7 59 63 83 F6 D4 3B 0E 10 00
V2Gframe (28bytes) = 01 FE 90 01 00 00 00 14 FE 80 00 00 00 00 00 00 05 A3 B7 59 63 83 F6 D4 3B 0E 10 00
[194321ms] Connection from ('fe80::ee65:ccff:feb6:85dc', 49153, 0, 4)
[SNIFFER] EXI from 49153 to 15118 (34bytes) = 80 00 DB AB 93 71 D3 23 4B 71 D1 B9 81 89 91 89 D1 91 81 89 91 D2 6B 9B 3A 23 2B 30 02 00 00 00 00 40
[194360ms] [EVSE] In state WaitForSupportedApplicationProtocolRequest, received (42bytes) = 01 FE 80 01 00 00 00 22 80 00 DB AB 93 71 D3 23 4B 71 D1 B9 81 89 91 89 D1 91 81 89 91 D2 6B 9B 3A 23 2B 30 02 00 00 00 00 40
[194375ms] [EVSE] {
"msgName": "supportedAppProtocolReq",
"info": "34 bytes to convert",
"error": "",
"result": "Vehicle supports 1 protocols. ProtocolEntry#1 ProtocolNamespace=urn:din:70121:2012:MsgDef Version=2.0 SchemaID=0 Priority=1 ",
"schema": "appHandshake",
"debug": ""
}
[194377ms] [EVSE] Detected DIN
[194392ms] [EVSE] responding (12bytes) = 01 FE 80 01 00 00 00 04 80 40 00 40
[194397ms] [EVSE] from 0 entering 1
[SNIFFER] EXI from 15118 to 49153 (4bytes) = 80 40 00 40
[194446ms] connection closed
[194450ms] [EVSE] re-initializing fsmEvse due to broken connection
[194451ms] [EVSE] re-initializing fsmEvse
[194451ms] Trying to reset the TCP socket
[194455ms] pyPlcTcpSocket listening on port 15118
[194456ms] The socket is linked the following IP addresses:
[194457ms] ::1
[194457ms] ::1
[194457ms] ::1
[196009ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[198796ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[201580ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5

pi@rpievse:~/myprogs/pyPlc $ python pyPlc.py E
starting in EvseMode
initializing pyPlcWorker
[addressManager] we have local MAC 52:D2:E4:36:AE:06.
[addressManager] Found 1 link-local IPv6 addresses.
fe80::5a3:b759:6383:f6d4
[addressManager] Local IPv6 is fe80::5a3:b759:6383:f6d4
Linux interface is eth1
[addressManager] will give local MAC 52:D2:E4:36:AE:06
[addressManager] will give local MAC 52:D2:E4:36:AE:06
pyPlcIpv6 started with ownMac 52:D2:E4:36:AE:06
[addressManager] will give local MAC 52:D2:E4:36:AE:06
udplog started with ownMac 52:D2:E4:36:AE:06
logging to UDP Syslog is enabled
sniffer created at eth1
[422ms] [HARDWAREINTERFACE] Auto detection of serial ports. Available serial ports:
[437ms] [HARDWAREINTERFACE] ignoring /dev/ttyAMA0, because this is not an USB serial port
[438ms] [HARDWAREINTERFACE] ERROR: No serial ports found. No hardware interaction possible.
[457ms] [pyPlcWorker] Software version v0.8-18-g2b87bca
[458ms] [EVSE] initializing fsmEvse
[461ms] pyPlcTcpSocket listening on port 15118
[461ms] rpievse
[470ms] The socket is linked the following IP addresses:
[470ms] ::1
[470ms] ::1
[470ms] ::1
[501ms] [CONNMGR] ConnectionLevel changed from 0 to 5
[502ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[504ms] transmitting SET_KEY.REQ, to configure the EVSE modem with random NMK
[537ms] received SET_KEY.CNF
[538ms] SetKeyCnf says 1, this is formally 'rejected', but indeed ok.
[572ms] [CONNMGR] ConnectionLevel changed from 5 to 15
[1590ms] [CONNMGR] 9 0 0 463 0 0 0  --> 15
[2692ms] [CONNMGR] 9 0 0 430 0 0 0  --> 15
[3796ms] [CONNMGR] 9 0 0 397 0 0 0  --> 15
[4908ms] [CONNMGR] 9 0 0 364 0 0 0  --> 15
[6008ms] [CONNMGR] 9 0 0 331 0 0 0  --> 15
[7109ms] [CONNMGR] 9 0 0 298 0 0 0  --> 15
[8209ms] [CONNMGR] 9 0 0 265 0 0 0  --> 15
[9311ms] [CONNMGR] 9 0 0 232 0 0 0  --> 15
[12092ms] [CONNMGR] 9 0 0 199 0 0 0  --> 15
[14875ms] [CONNMGR] 9 0 0 166 0 0 0  --> 15
[15468ms] received SLAC_PARAM.REQ
[addressManager] pev has MAC EC:65:CC:B6:85:DC
[15477ms] [EVSE] transmitting CM_SLAC_PARAM.CNF
[15733ms] received MNBC_SOUND.IND
[15738ms] received MNBC_SOUND.IND
[15826ms] received MNBC_SOUND.IND
[15829ms] received MNBC_SOUND.IND
[15832ms] received MNBC_SOUND.IND
[15835ms] received MNBC_SOUND.IND
[15922ms] received MNBC_SOUND.IND
[15925ms] received MNBC_SOUND.IND
[15928ms] received MNBC_SOUND.IND
[16015ms] received MNBC_SOUND.IND
[16017ms] [EVSE] transmitting ATTEN_CHAR.IND
[16863ms] received SLAC_MATCH.REQ
[16869ms] [EVSE] transmitting SLAC_MATCH.CNF
[17715ms] [CONNMGR] 9 0 0 133 0 0 0  --> 15
[20499ms] [CONNMGR] 9 0 0 100 0 0 0  --> 15
[addressManager] pev has IP fe80:0000:0000:0000:ee65:ccff:feb6:85dc
V2GTP (10bytes) = 01 FE 90 00 00 00 00 02 10 00
Ok, this was a valid SDP request. We are the SECC. Sending SDP response.
SDP payload (20bytes) = FE 80 00 00 00 00 00 00 05 A3 B7 59 63 83 F6 D4 3B 0E 10 00
V2Gframe (28bytes) = 01 FE 90 01 00 00 00 14 FE 80 00 00 00 00 00 00 05 A3 B7 59 63 83 F6 D4 3B 0E 10 00
[SNIFFER] EXI from 49153 to 15118 (34bytes) = 80 00 DB AB 93 71 D3 23 4B 71 D1 B9 81 89 91 89 D1 91 81 89 91 D2 6B 9B 3A 23 2B 30 02 00 00 00 00 40
[21356ms] Connection from ('fe80::ee65:ccff:feb6:85dc', 49153, 0, 4)
[21394ms] [EVSE] In state WaitForSupportedApplicationProtocolRequest, received (42bytes) = 01 FE 80 01 00 00 00 22 80 00 DB AB 93 71 D3 23 4B 71 D1 B9 81 89 91 89 D1 91 81 89 91 D2 6B 9B 3A 23 2B 30 02 00 00 00 00 40
[21409ms] [EVSE] {
"msgName": "supportedAppProtocolReq",
"info": "34 bytes to convert",
"error": "",
"result": "Vehicle supports 1 protocols. ProtocolEntry#1 ProtocolNamespace=urn:din:70121:2012:MsgDef Version=2.0 SchemaID=0 Priority=1 ",
"schema": "appHandshake",
"debug": ""
}
[21411ms] [EVSE] Detected DIN
[21423ms] [EVSE] responding (12bytes) = 01 FE 80 01 00 00 00 04 80 40 00 40
[21427ms] [EVSE] from 0 entering 1
[SNIFFER] EXI from 15118 to 49153 (4bytes) = 80 40 00 40
[21472ms] connection closed
[21477ms] [EVSE] re-initializing fsmEvse due to broken connection
[21477ms] [EVSE] re-initializing fsmEvse
[21478ms] Trying to reset the TCP socket
[21482ms] pyPlcTcpSocket listening on port 15118
[21483ms] The socket is linked the following IP addresses:
[21484ms] ::1
[21484ms] ::1
[21485ms] ::1
[23205ms] [CONNMGR] 9 0 0 67 0 0 0  --> 15
[25989ms] [CONNMGR] 9 0 0 34 0 0 0  --> 15
[28777ms] [CONNMGR] 9 0 0 1 0 0 0  --> 15
[28863ms] [CONNMGR] ConnectionLevel changed from 15 to 5
[31563ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[34349ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
[37135ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5

Any ideas about this? [21472ms] connection closed [21477ms] [EVSE] re-initializing fsmEvse due to broken connection [21477ms] [EVSE] re-initializing fsmEvse

[uhi22]

Hi,

regarding the exiConnector: Yes, this is a confusing error, which is in fact no error. I just pushed an improvement.

Regarding the closed connection, it is unclear which side closes the TCP connection, and why. Is it possible to create a network log with wireshark or tcpdump? (Edith) Maybe the car does not accept the protocol handshake response. May I ask what type of car this is?

[fluppie]

Jup, exiConnector.py works now :) I can, is their a manual/instruction on how to do it? Or is this already happening in the background. 2022 BMW iX3

[uhi22]

No, in EvseMode there is no script / service, which would run in background and do the logging. (This is in contrast to the PevMode, where we have the starter.sh, which starts the tcpdump and the pevNoGui script.) If you have a display and keyboard at your device and boot to the desktop, you can install wireshark using "sudo apt-get install wireshark", and then open the wireshark and select the appropriate interface for tracing. If you have only a command line, something like sudo tcpdump -i "eth0" -w "mydumpfile.pcap" & should do the job. This starts the tcpdump in the background (using the & at the end), and allows to call the python script afterwards.

[fluppie]

I think I have something, hopefully it makes senses to you. I put the PWM 2 times to 5% for about 1 min. BMWiX3.zip

And some more BMWiX3_2.zip BMWiX3_ModemRequest.zip

[uhi22]

The tracing worked perfectly. The traces show multiple times the issue with the broken connection, and the situation is always the same: After the TCP connection is correctly established, the iX3 announces the list of supported protocols, in this case the list contains one entry: DIN 70121 from 2012 (btw: This is surprising, this nearly brand-new car does not support ISO 15118, only the 10 year old DIN spec). The evse selects the first entry of the list, and the iX3 confirms this message with an TCP ACK. Afterwards it closes actively the TCP connection. It is not clear at the moment, why this is the case. The response of the evse is the same as also public chargers are using.

[uhi22]

One idea: Maybe the car is confused about the lots of debug messages, which the evse sends as UDP broadcasts. I is worth a try to set udp_syslog_enable = No in pyPlc.ini.

[fluppie]

BMWiX3_noudplog.zip

Looks like it doesn't help :(. Yes, BMW announced plug & charge to be available mid 2023, but not for which models...

 rpievse python3.9[12558]: [182010ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
Jun 22 00:31:34 rpievse python3.9[12558]: [184685ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
Jun 22 00:31:35 rpievse python3.9[12558]: [185335ms] received SLAC_PARAM.REQ
Jun 22 00:31:35 rpievse python3.9[12558]: [addressManager] pev has MAC EC:65:CC:B6:85:DC
Jun 22 00:31:35 rpievse python3.9[12558]: [185336ms] [EVSE] transmitting CM_SLAC_PARAM.CNF
Jun 22 00:31:35 rpievse python3.9[12558]: [185499ms] received SLAC_PARAM.REQ
Jun 22 00:31:35 rpievse python3.9[12558]: [addressManager] pev has MAC EC:65:CC:B6:85:DC
Jun 22 00:31:35 rpievse python3.9[12558]: [185500ms] [EVSE] transmitting CM_SLAC_PARAM.CNF
Jun 22 00:31:35 rpievse python3.9[12558]: [185745ms] received MNBC_SOUND.IND
Jun 22 00:31:35 rpievse python3.9[12558]: [185745ms] received MNBC_SOUND.IND
Jun 22 00:31:35 rpievse python3.9[12558]: [185827ms] received MNBC_SOUND.IND
Jun 22 00:31:35 rpievse python3.9[12558]: [185909ms] received MNBC_SOUND.IND
Jun 22 00:31:35 rpievse python3.9[12558]: [185991ms] received MNBC_SOUND.IND
Jun 22 00:31:35 rpievse python3.9[12558]: [185991ms] received MNBC_SOUND.IND
Jun 22 00:31:37 rpievse python3.9[12558]: [187369ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
Jun 22 00:31:37 rpievse python3.9[12558]: [187938ms] received SLAC_PARAM.REQ
Jun 22 00:31:37 rpievse python3.9[12558]: [addressManager] pev has MAC EC:65:CC:B6:85:DC
Jun 22 00:31:37 rpievse python3.9[12558]: [187938ms] [EVSE] transmitting CM_SLAC_PARAM.CNF
Jun 22 00:31:37 rpievse python3.9[12558]: [188183ms] received MNBC_SOUND.IND
Jun 22 00:31:37 rpievse python3.9[12558]: [188183ms] received MNBC_SOUND.IND
Jun 22 00:31:38 rpievse python3.9[12558]: [188265ms] received MNBC_SOUND.IND
Jun 22 00:31:38 rpievse python3.9[12558]: [188266ms] received MNBC_SOUND.IND
Jun 22 00:31:38 rpievse python3.9[12558]: [188266ms] received MNBC_SOUND.IND
Jun 22 00:31:38 rpievse python3.9[12558]: [188348ms] received MNBC_SOUND.IND
Jun 22 00:31:38 rpievse python3.9[12558]: [188350ms] received MNBC_SOUND.IND
Jun 22 00:31:38 rpievse python3.9[12558]: [188434ms] received MNBC_SOUND.IND
Jun 22 00:31:38 rpievse python3.9[12558]: [188437ms] received MNBC_SOUND.IND
Jun 22 00:31:38 rpievse python3.9[12558]: [188438ms] received MNBC_SOUND.IND
Jun 22 00:31:38 rpievse python3.9[12558]: [188439ms] [EVSE] transmitting ATTEN_CHAR.IND
Jun 22 00:31:39 rpievse python3.9[12558]: [189332ms] received SLAC_MATCH.REQ
Jun 22 00:31:39 rpievse python3.9[12558]: [189332ms] [EVSE] transmitting SLAC_MATCH.CNF
Jun 22 00:31:39 rpievse python3.9[12558]: [190063ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
Jun 22 00:31:42 rpievse python3.9[12558]: [addressManager] pev has IP fe80:0000:0000:0000:ee65:ccff:feb6:85dc
Jun 22 00:31:42 rpievse python3.9[12558]: V2GTP (10bytes) = 01 FE 90 00 00 00 00 02 10 00
Jun 22 00:31:42 rpievse python3.9[12558]: Ok, this was a valid SDP request. We are the SECC. Sending SDP response.
Jun 22 00:31:42 rpievse python3.9[12558]: SDP payload (20bytes) = FE 80 00 00 00 00 00 00 DA F2 AE 7A DB 60 D6 A9 3B 0E 10 00
Jun 22 00:31:42 rpievse python3.9[12558]: V2Gframe (28bytes) = 01 FE 90 01 00 00 00 14 FE 80 00 00 00 00 00 00 DA F2 AE 7A DB 60 D6 A9 3B 0E 10 00
Jun 22 00:31:42 rpievse python3.9[12558]: [192740ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
Jun 22 00:31:42 rpievse python3.9[12558]: [192743ms] Connection from ('fe80::ee65:ccff:feb6:85dc', 49155, 0, 4)
Jun 22 00:31:42 rpievse python3.9[12558]: [SNIFFER] EXI from 49155 to 15118 (34bytes) = 80 00 DB AB 93 71 D3 23 4B 71 D1 B9 81 89 91 89 D1 91 81 89 91 D2 6B 9B 3A 23 2B 30 02 00 00 00 00 40
Jun 22 00:31:42 rpievse python3.9[12558]: [192775ms] [EVSE] In state WaitForSupportedApplicationProtocolRequest, received (42bytes) = 01 FE 80 01 00 00 00 22 80 00 DB AB 93 71 D3 23 4B 71 D1 B9 81 89 91 89 D1 91 81 89 91 D2 6B 9B 3A 23 2B 30 02 00 00 00 00 40
Jun 22 00:31:42 rpievse python3.9[12558]: [192789ms] [EVSE] {
Jun 22 00:31:42 rpievse python3.9[12558]: "msgName": "supportedAppProtocolReq",
Jun 22 00:31:42 rpievse python3.9[12558]: "info": "34 bytes to convert",
Jun 22 00:31:42 rpievse python3.9[12558]: "error": "",
Jun 22 00:31:42 rpievse python3.9[12558]: "result": "Vehicle supports 1 protocols. ProtocolEntry#1 ProtocolNamespace=urn:din:70121:2012:MsgDef Version=2.0 SchemaID=0 Priority=1 ",
Jun 22 00:31:42 rpievse python3.9[12558]: "schema": "appHandshake",
Jun 22 00:31:42 rpievse python3.9[12558]: "debug": ""
Jun 22 00:31:42 rpievse python3.9[12558]: }
Jun 22 00:31:42 rpievse python3.9[12558]: [192789ms] [EVSE] Detected DIN
Jun 22 00:31:42 rpievse python3.9[12558]: [192803ms] [EVSE] responding (12bytes) = 01 FE 80 01 00 00 00 04 80 40 00 40
Jun 22 00:31:42 rpievse python3.9[12558]: [192804ms] [EVSE] from 0 entering 1
Jun 22 00:31:42 rpievse python3.9[12558]: [SNIFFER] EXI from 15118 to 49155 (4bytes) = 80 40 00 40
Jun 22 00:31:42 rpievse python3.9[12558]: [192855ms] connection closed
Jun 22 00:31:42 rpievse python3.9[12558]: [192855ms] [EVSE] re-initializing fsmEvse due to broken connection
Jun 22 00:31:42 rpievse python3.9[12558]: [192855ms] [EVSE] re-initializing fsmEvse
Jun 22 00:31:42 rpievse python3.9[12558]: [192855ms] Trying to reset the TCP socket
Jun 22 00:31:42 rpievse python3.9[12558]: [192856ms] pyPlcTcpSocket listening on port 15118
Jun 22 00:31:42 rpievse python3.9[12558]: [192857ms] The socket is linked the following IP addresses:
Jun 22 00:31:42 rpievse python3.9[12558]: [192857ms] ::1
Jun 22 00:31:42 rpievse python3.9[12558]: [192857ms] ::1
Jun 22 00:31:42 rpievse python3.9[12558]: [192857ms] ::1
Jun 22 00:31:45 rpievse python3.9[12558]: [195318ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5
Jun 22 00:31:47 rpievse python3.9[12558]: [197993ms] [CONNMGR] 9 0 0 0 0 0 0  --> 5

[uhi22]

Does the same setup work with other car types?

[fluppie]

On Sunday a friend with a Tesla Model 3 will come over, hopefully that will work, so we know if it's the iX3 or not.

[uhi22]

I think I got the point: The iX3 uses SchemaID 0, but others (Tesla, Ioniq) use SchemaID 1. The pyPLC is hardwired to request Schema 1, which of course does not fit to the announcement of the iX3. Updates of the fsmEvse and the openV2Gx are necessary to be more flexible...

[fluppie]

OK, and is this a complex thing to change? I have no clue what would be the difference between SchemaID 0 and SchemaID 1 :). Or can you just hardcode the SchemaID 0 where the 1 is mentioned?

P.S.: This is the log from the Tesla. pyPlc_logs_1day.txt Out of 9 "received SLAC_PARAM.REQ" I only have 2 "DC_EVStatus.EVRESSSOC"

[uhi22]

The SchemaID is just a number. The car just gives a number to each entry in the list of supported protocols, and the charger picks one entry by telling "I want schemaID 1". In this response, the SchemaID is even optional, so the charger is formally allowed to say "I want", without telling a number. I have no idea, whether this works, but if you want to give a try you could search for aphsDoc.supportedAppProtocolRes.SchemaID = 1; in the openV2Gx, and change the number, or, more interesting, change the "isUsed" to 0 and test whether the car is happy with it.

[uhi22]

The clean fix would be: Run through the list of announced protocols, extract the protocol and SchemaID of each entry, find the DIN entry, take the SchemaID of this entry, and send it to the car.

[uhi22]

Since the topic mentioned in the title is solved, I created issues #9 and issue #10 for the remaining topics, and close this one.