EcoG-io/iso15118

Running Josev/ISO15118 in Docker on Raspberry Pi: EVCC terminates data link for no apparent reason

alexander-kurz opened this issue · 1 comments

I'm trying to run Josev/ISO15118 in Docker on a Raspberry Pi 3 Model B Rev 1.2 with Raspberry Pi OS Desktop, but the EVCC side terminates the data link at seemingly random point (often after entering state ServiceDiscovery or PowerDelivery).

I only modified the .env.dev.docker with MESSAGE_LOG_EXI=True.

This is the relevant output from sudo make build && sudo make dev:

[+] Running 3/3
 ✔ Container iso15118-redis-1  Created                                                                                                                 0.0s 
 ✔ Container iso15118-secc-1   Recreated                                                                                                               0.7s 
 ✔ Container iso15118-evcc-1   Recreated                                                                                                               0.5s 
Attaching to iso15118-evcc-1, iso15118-redis-1, iso15118-secc-1
iso15118-redis-1  | 1:C 27 Apr 2023 07:50:28.689 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
iso15118-redis-1  | 1:C 27 Apr 2023 07:50:28.689 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=1, just started
iso15118-redis-1  | 1:C 27 Apr 2023 07:50:28.689 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.694 * monotonic clock: POSIX clock_gettime
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.701 * Running mode=standalone, port=6379.
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.702 # Server initialized
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.704 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.721 * Loading RDB produced by version 6.2.6
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.722 * RDB age 347 seconds
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.723 * RDB memory usage when created 0.80 Mb
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.724 # Done loading RDB, keys loaded: 0, keys expired: 0.
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.724 * DB loaded from disk: 0.006 seconds
iso15118-redis-1  | 1:M 27 Apr 2023 07:50:28.725 * Ready to accept connections
iso15118-evcc-1   | Waiting for 5 seconds to start EVCC
iso15118-secc-1   | DEBUG    2023-04-27 07:50:37,341 - asyncio (59): Using selector: EpollSelector
iso15118-secc-1   | INFO    2023-04-27 07:50:37,353 - iso15118.secc.secc_settings (110): SECC settings:
iso15118-secc-1   | INFO    2023-04-27 07:50:37,354 - iso15118.secc.secc_settings (112): PKI_PATH                      : /venv/lib/python3.10/site-packages/iso15118/shared/pki
iso15118-secc-1   | INFO    2023-04-27 07:50:37,355 - iso15118.secc.secc_settings (112): MESSAGE_LOG_JSON              : True
iso15118-secc-1   | INFO    2023-04-27 07:50:37,357 - iso15118.secc.secc_settings (112): ENABLE_TLS_1_3                : False
iso15118-secc-1   | INFO    2023-04-27 07:50:37,358 - iso15118.secc.secc_settings (112): V20_SERVICE_CONFIG            : /venv/lib/python3.10/site-packages/iso15118/shared/examples/secc/15118_20/service_config.json
iso15118-secc-1   | INFO    2023-04-27 07:50:37,358 - iso15118.secc.secc_settings (112): MESSAGE_LOG_EXI               : True
iso15118-secc-1   | INFO    2023-04-27 07:50:37,365 - iso15118.secc.secc_settings (114): PROTOCOLS                     : ['DIN_SPEC_70121', 'ISO_15118_2', 'ISO_15118_20_AC', 'ISO_15118_20_DC']
iso15118-secc-1   | INFO    2023-04-27 07:50:37,367 - iso15118.secc.secc_settings (114): LOG_LEVEL                     : DEBUG
iso15118-secc-1   | INFO    2023-04-27 07:50:37,368 - iso15118.secc.secc_settings (114): NETWORK_INTERFACE             : eth0
iso15118-secc-1   | INFO    2023-04-27 07:50:37,369 - iso15118.secc.secc_settings (114): SECC_ENFORCE_TLS              : False
iso15118-secc-1   | INFO    2023-04-27 07:50:37,370 - iso15118.secc.secc_settings (114): FREE_CHARGING_SERVICE         : False
iso15118-secc-1   | INFO    2023-04-27 07:50:37,371 - iso15118.secc.secc_settings (114): USE_CPO_BACKEND               : False
iso15118-secc-1   | INFO    2023-04-27 07:50:37,372 - iso15118.secc.secc_settings (114): STANDBY_ALLOWED               : False
iso15118-secc-1   | INFO    2023-04-27 07:50:37,373 - iso15118.secc.secc_settings (114): AUTH_MODES                    : ['EIM', 'PNC']
iso15118-secc-1   | INFO    2023-04-27 07:50:37,374 - iso15118.secc.secc_settings (114): FREE_CERT_INSTALL_SERVICE     : True
iso15118-secc-1   | INFO    2023-04-27 07:50:37,375 - iso15118.secc.secc_settings (114): ALLOW_CERT_INSTALL_SERVICE    : True
iso15118-secc-1   | DEBUG    2023-04-27 07:50:37,440 - iso15118.secc.controller.simulator (204): New Status: starting
iso15118-evcc-1   | DEBUG    2023-04-27 07:50:45,547 - asyncio (59): Using selector: EpollSelector
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,558 - iso15118.evcc.evcc_settings (45): EVCC environment settings:
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,559 - iso15118.evcc.evcc_settings (47): V20_SERVICE_CONFIG            : /venv/lib/python3.10/site-packages/iso15118/shared/examples/secc/15118_20/service_config.json
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,561 - iso15118.evcc.evcc_settings (47): PKI_PATH                      : /venv/lib/python3.10/site-packages/iso15118/shared/pki
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,563 - iso15118.evcc.evcc_settings (47): MESSAGE_LOG_JSON              : True
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,565 - iso15118.evcc.evcc_settings (47): ENABLE_TLS_1_3                : False
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,566 - iso15118.evcc.evcc_settings (47): MESSAGE_LOG_EXI               : True
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,574 - iso15118.evcc.evcc_settings (49): LOG_LEVEL                     : DEBUG
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,575 - iso15118.evcc.evcc_settings (49): NETWORK_INTERFACE             : eth0
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,577 - iso15118.evcc.evcc_settings (49): EVCC_CONFIG_PATH              : iso15118/shared/examples/evcc/iso15118_2/evcc_config_eim_ac.json
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,634 - iso15118.evcc.evcc_config (115): EVCC Settings
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,637 - iso15118.evcc.evcc_config (118): supported_energy_services     : [<ServiceV20.AC: 1>]
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,638 - iso15118.evcc.evcc_config (118): is_cert_install_needed        : False
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,639 - iso15118.evcc.evcc_config (118): use_tls                       : False
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,640 - iso15118.evcc.evcc_config (118): sdp_retry_cycles              : 1
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,641 - iso15118.evcc.evcc_config (118): max_contract_certs            : 3
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,642 - iso15118.evcc.evcc_config (118): enforce_tls                   : False
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,643 - iso15118.evcc.evcc_config (118): supported_protocols           : [<Protocol.ISO_15118_2: (<Namespace.ISO_V2_MSG_DEF: 'urn:iso:15118:2:2013:MsgDef'>, <enum 'ISOV2PayloadTypes'>)>]
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,645 - iso15118.evcc.evcc_config (118): energy_transfer_mode          : AC_three_phase_core
iso15118-evcc-1   | INFO    2023-04-27 07:50:45,646 - iso15118.evcc.evcc_config (118): max_supporting_points         : 1024
iso15118-secc-1   | INFO    2023-04-27 07:50:52,918 - iso15118.shared.exi_codec (174): EXI Codec version: 1.55
iso15118-secc-1   | INFO    2023-04-27 07:50:52,920 - iso15118.secc (31): Starting 15118 version: 0.21.0
iso15118-secc-1   | INFO    2023-04-27 07:50:52,922 - iso15118.secc.comm_session_handler (210): Communication session handler started
iso15118-secc-1   | INFO    2023-04-27 07:50:52,943 - iso15118.secc.transport.udp_server (134): UDP server socket ready
iso15118-secc-1   | INFO    2023-04-27 07:50:52,945 - iso15118.secc.transport.udp_server (120): UDP server started at address FF02::1%eth0 and port 15118
iso15118-secc-1   | DEBUG    2023-04-27 07:50:52,957 - iso15118.secc.controller.simulator (204): New Status: ready
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,263 - iso15118.shared.exi_codec (174): EXI Codec version: 1.55
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,264 - iso15118.evcc (30): Starting 15118 version: 0.21.0
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,266 - iso15118.evcc.comm_session_handler (307): Communication session handler started
iso15118-evcc-1   | DEBUG    2023-04-27 07:51:05,283 - iso15118.evcc.comm_session_handler (386): Initiating new SDP cycle, 0 more cycles(s) left
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,284 - iso15118.evcc.comm_session_handler (392): Remaining SDP requests: 50
iso15118-evcc-1   | DEBUG    2023-04-27 07:51:05,285 - iso15118.evcc.transport.udp_client (90): UDP client socket ready
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,387 - iso15118.evcc.comm_session_handler (329): Sending SDPRequest: [Security: NO_TLS, Protocol: TCP]
iso15118-secc-1   | DEBUG    2023-04-27 07:51:05,390 - iso15118.secc.transport.udp_server (155): Message received from ('fe80::42:acff:fe12:3', 52458, 0, 40): 01fe9000000000021000
iso15118-evcc-1   | DEBUG    2023-04-27 07:51:05,391 - iso15118.evcc.transport.udp_client (170): Message sent: [Header = [0x1, 0xfe, 0x9000, 2], Payload = 1000)]
iso15118-secc-1   | INFO    2023-04-27 07:51:05,392 - iso15118.secc.comm_session_handler (350): SDPRequest received: [Security: NO_TLS, Protocol: TCP]
iso15118-secc-1   | INFO    2023-04-27 07:51:05,400 - iso15118.secc.transport.tcp_server (136): TCP server started at address fe80::42:acff:fe12:2%eth0 and port 60001
iso15118-secc-1   | INFO    2023-04-27 07:51:05,410 - iso15118.secc.comm_session_handler (392): Sending SDPResponse: [ IP address: fe80::42:acff:fe12:2, Port: 60001 , Security: NO_TLS , Transport: TCP ]
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,412 - iso15118.evcc.transport.udp_client (105): Received datagram from UDP server at address ('fe80::42:acff:fe12:2', 15118, 0, 42)
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,418 - iso15118.evcc.comm_session_handler (475): SDPResponse received: [ IP address: fe80::42:acff:fe12:2, Port: 60001 , Security: NO_TLS , Transport: TCP ]
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,432 - iso15118.evcc.comm_session_handler (410): Starting TCP client, trying to connect to fe80::42:acff:fe12:2 at port 60001 ...
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,439 - iso15118.evcc.comm_session_handler (417): TCP client connected
iso15118-secc-1   | INFO    2023-04-27 07:51:05,440 - iso15118.secc.transport.udp_server (198): UDP server has been paused.
iso15118-secc-1   | INFO    2023-04-27 07:51:05,441 - iso15118.secc.comm_session_handler (258): TCP client connected, client address is ('fe80::42:acff:fe12:3', 51500, 0, 40).
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,525 - iso15118.shared.comm_session (345): Starting a new communication session
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,528 - iso15118.shared.states (139): Entered state SupportedAppProtocol
iso15118-evcc-1   | DEBUG    2023-04-27 07:51:05,529 - iso15118.shared.states (143): Waiting for up to 2.0 s
iso15118-evcc-1   | INFO    2023-04-27 07:51:05,536 - iso15118.shared.exi_codec (245): Message to encode (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolReq": {"AppProtocol": [{"ProtocolNamespace": "urn:iso:15118:2:2013:MsgDef", "VersionNumberMajor": 2, "VersionNumberMinor": 0, "SchemaID": 1, "Priority": 1}]}}
iso15118-secc-1   | INFO    2023-04-27 07:51:05,545 - iso15118.shared.comm_session (345): Starting a new communication session
iso15118-secc-1   | INFO    2023-04-27 07:51:05,547 - iso15118.shared.states (139): Entered state SupportedAppProtocol
iso15118-secc-1   | DEBUG    2023-04-27 07:51:05,555 - iso15118.shared.states (143): Waiting for up to 20.0 s
iso15118-evcc-1   | DEBUG    2023-04-27 07:51:06,011 - iso15118.shared.exi_codec (256): EXI-encoded message: 8000ebab9371d34b9b79d189a98989c1d191d191818999d26b9b3a232b30020000040040
iso15118-evcc-1   | INFO    2023-04-27 07:51:06,013 - iso15118.shared.comm_session (418): Sending supportedAppProtocolReq
iso15118-secc-1   | DEBUG    2023-04-27 07:51:06,016 - iso15118.shared.exi_codec (282): EXI-encoded message (ns=urn:iso:15118:2:2010:AppProtocol): 8000ebab9371d34b9b79d189a98989c1d191d191818999d26b9b3a232b30020000040040
iso15118-secc-1   | INFO    2023-04-27 07:51:07,053 - iso15118.shared.exi_codec (299): Decoded message (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolReq":{"AppProtocol":[{"ProtocolNamespace":"urn:iso:15118:2:2013:MsgDef","VersionNumberMajor":2,"VersionNumberMinor":0,"SchemaID":1,"Priority":1}]}}
iso15118-secc-1   | INFO    2023-04-27 07:51:07,056 - iso15118.shared.comm_session (234): supportedAppProtocolReq received
iso15118-secc-1   | INFO    2023-04-27 07:51:07,059 - iso15118.shared.exi_codec (245): Message to encode (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolRes": {"ResponseCode": "OK_SuccessfulNegotiation", "SchemaID": 1}}
iso15118-secc-1   | DEBUG    2023-04-27 07:51:07,373 - iso15118.shared.exi_codec (256): EXI-encoded message: 80400040
iso15118-secc-1   | INFO    2023-04-27 07:51:07,374 - iso15118.secc.states.sap_states (147): Chosen protocol: ISO_15118_2
iso15118-secc-1   | INFO    2023-04-27 07:51:07,376 - iso15118.shared.comm_session (418): Sending supportedAppProtocolRes
iso15118-secc-1   | INFO    2023-04-27 07:51:07,378 - iso15118.shared.states (139): Entered state SessionSetup
iso15118-secc-1   | DEBUG    2023-04-27 07:51:07,379 - iso15118.shared.states (143): Waiting for up to 20.0 s
iso15118-evcc-1   | DEBUG    2023-04-27 07:51:07,379 - iso15118.shared.exi_codec (282): EXI-encoded message (ns=urn:iso:15118:2:2010:AppProtocol): 80400040
iso15118-evcc-1   | INFO    2023-04-27 07:51:08,128 - iso15118.shared.exi_codec (299): Decoded message (ns=urn:iso:15118:2:2010:AppProtocol): {"supportedAppProtocolRes":{"ResponseCode":"OK_SuccessfulNegotiation","SchemaID":1}}
iso15118-evcc-1   | INFO    2023-04-27 07:51:08,129 - iso15118.shared.comm_session (234): supportedAppProtocolRes received
iso15118-evcc-1   | INFO    2023-04-27 07:51:08,133 - iso15118.evcc.states.sap_states (153): Chosen protocol: ISO_15118_2
iso15118-evcc-1   | INFO    2023-04-27 07:51:08,137 - iso15118.shared.exi_codec (245): Message to encode (ns=urn:iso:15118:2:2013:MsgDef): {"V2G_Message": {"Header": {"SessionID": "00"}, "Body": {"SessionSetupReq": {"EVCCID": "0242AC120003"}}}}
iso15118-evcc-1   | DEBUG    2023-04-27 07:51:09,517 - iso15118.shared.exi_codec (256): EXI-encoded message: 8098004011d018090ab048000c00
iso15118-evcc-1   | INFO    2023-04-27 07:51:09,518 - iso15118.shared.comm_session (418): Sending SessionSetupReq
iso15118-evcc-1   | INFO    2023-04-27 07:51:09,520 - iso15118.shared.states (139): Entered state SessionSetup
iso15118-evcc-1   | DEBUG    2023-04-27 07:51:09,521 - iso15118.shared.states (143): Waiting for up to 20.0 s
iso15118-secc-1   | DEBUG    2023-04-27 07:51:09,521 - iso15118.shared.exi_codec (282): EXI-encoded message (ns=urn:iso:15118:2:2013:MsgDef): 8098004011d018090ab048000c00
iso15118-secc-1   | INFO    2023-04-27 07:51:11,031 - iso15118.shared.exi_codec (299): Decoded message (ns=urn:iso:15118:2:2013:MsgDef): {"V2G_Message":{"Header":{"SessionID":"00"},"Body":{"SessionSetupReq":{"EVCCID":"0242AC120003"}}}}
iso15118-secc-1   | INFO    2023-04-27 07:51:11,034 - iso15118.shared.comm_session (234): SessionSetupReq received
iso15118-secc-1   | INFO    2023-04-27 07:51:11,040 - iso15118.shared.exi_codec (245): Message to encode (ns=urn:iso:15118:2:2013:MsgDef): {"V2G_Message": {"Header": {"SessionID": "FD79E36047A87BCC"}, "Body": {"SessionSetupRes": {"ResponseCode": "OK_NewSessionEstablished", "EVSEID": "UK123E1234", "EVSETimeStamp": 1682581871}}}}
iso15118-evcc-1   | INFO    2023-04-27 07:51:11,526 - iso15118.shared.comm_session (391): The data link will terminate in 2 seconds and the TCP connection will close in 5 seconds. 
iso15118-evcc-1   | INFO    2023-04-27 07:51:11,527 - iso15118.shared.comm_session (395): Reason: TimeoutError occurred. Waited for 2.0 s after sending last message: [Header = [0x1, 0xfe, 0x8001, 14], Payload = 8098004011d018090ab048000c00)]
iso15118-secc-1   | DEBUG    2023-04-27 07:51:12,171 - iso15118.shared.exi_codec (256): EXI-encoded message: 8098023f5e78d811ea1ef311e02031552cc4c8cd14c4c8ccd01dfa551440c0
iso15118-secc-1   | INFO    2023-04-27 07:51:12,172 - iso15118.shared.comm_session (418): Sending SessionSetupRes
iso15118-secc-1   | INFO    2023-04-27 07:51:12,174 - iso15118.shared.states (139): Entered state ServiceDiscovery
iso15118-secc-1   | DEBUG    2023-04-27 07:51:12,176 - iso15118.shared.states (143): Waiting for up to 60.0 s
iso15118-evcc-1   | INFO    2023-04-27 07:51:13,530 - iso15118.shared.comm_session (402): terminated the data link
iso15118-evcc-1   | INFO    2023-04-27 07:51:16,536 - iso15118.shared.comm_session (409): TCP connection closed to peer with address ('fe80::42:acff:fe12:2', 60001, 0, 42)
iso15118-secc-1   | INFO    2023-04-27 07:51:16,538 - iso15118.shared.comm_session (391): The data link will terminate in 2 seconds and the TCP connection will close in 5 seconds. 
iso15118-secc-1   | INFO    2023-04-27 07:51:16,539 - iso15118.shared.comm_session (395): Reason: TCP peer closed connection
iso15118-evcc-1   | ERROR    2023-04-27 07:51:16,538 - iso15118.evcc.comm_session_handler (557): EVCC tried to initiate a V2GCommunicationSession, but maximum number of SDP retry cycles (1) is now reached. Shutting down high-level communication. Unplug and plug in the cable again if you want to start anew.
iso15118-evcc-1   | Traceback (most recent call last):
iso15118-evcc-1   |   File "/venv/lib/python3.10/site-packages/iso15118/evcc/comm_session_handler.py", line 555, in get_from_rcv_queue
iso15118-evcc-1   |     await self.restart_sdp(True)
iso15118-evcc-1   |   File "/venv/lib/python3.10/site-packages/iso15118/evcc/comm_session_handler.py", line 378, in restart_sdp
iso15118-evcc-1   |     raise SDPFailedError(
iso15118-evcc-1   | iso15118.shared.exceptions.SDPFailedError: EVCC tried to initiate a V2GCommunicationSession, but maximum number of SDP retry cycles (1) is now reached. Shutting down high-level communication. Unplug and plug in the cable again if you want to start anew.
iso15118-secc-1   | INFO    2023-04-27 07:51:18,543 - iso15118.shared.comm_session (402): terminated the data link
iso15118-secc-1   | INFO    2023-04-27 07:51:21,549 - iso15118.shared.comm_session (409): TCP connection closed to peer with address ('fe80::42:acff:fe12:3', 51500, 0, 40)
iso15118-secc-1   | WARNING    2023-04-27 07:51:21,551 - iso15118.secc.transport.tcp_server (151): Closing TCP server
iso15118-secc-1   | INFO    2023-04-27 07:51:21,553 - iso15118.secc.transport.udp_server (206): UDP server has been resumed.

In another attempt I changed sdpRetryCycles to 5 in the config files. Here you can see how the EVCC terminates the data link at different times.
josev_docker_log_sdp5.txt

If you need further information, I'll be happy to provide it.
Any help is greatly appreciated.

Apologies for the super late response. Did you get to the bottom of this?
Also, do you see the same issue when you running it locally (as in, without the docker) as well?