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?