EVerest / everest-demo

EVerest demo: Dockerized demo with software in the loop simulation
Apache License 2.0
11 stars 13 forks source link

Add new single demo script for all ISO 15118-2 AC with OCPP demos #34

Closed activeshadow closed 3 months ago

activeshadow commented 3 months ago

This new script includes option flags for which demo to run.

It also enables the option to test a user's local copy of this repo without having to edit the script or push commits up to GitHub first.

Note that the OCPP v1.6j demo is currently not working with this new script (though it also wasn't working with the old script either).

references #25

activeshadow commented 3 months ago

@shankari please review!

activeshadow commented 3 months ago

@sahabulh just calling you out here for your situational awareness. Feel free to review as well!

shankari commented 3 months ago

I can confirm that the existing 1.6j demo works for me. See logs below + I can charge from the UI

everest-ac-demo-steve-1        | [INFO ] 2024-03-21 04:37:41,999 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp2069500590-42) - [chargeBoxId=cp001, sessionId=c277938a-58ee-87f2-50ca-a76c30aad446] Sending: [3,"52a87262-8e4b-4e2d-8b9d-9ca9f404bcc8",{"status":"Accepted"}]
everest-ac-demo-manager-1      | 2024-03-21 04:40:28.259061 [INFO] car_simulator_1  :: { cmd: 'sleep', args: [ 1 ], exec: [Function (anonymous)] }
everest-ac-demo-manager-1      | 2024-03-21 04:40:29.530606 [INFO] car_simulator_1  :: { cmd: 'iec_wait_pwr_ready', args: [], exec: [Function (anonymous)] }
everest-ac-demo-manager-1      | 2024-03-21 04:40:30.122966 [INFO] evse_manager_1:  :: SYS  Session logging started.
everest-ac-demo-manager-1      | 2024-03-21 04:40:30.138443 [INFO] evse_manager_1:  :: EVSE IEC Session Started: EVConnected
everest-ac-demo-manager-1      | 2024-03-21 04:40:30.144117 [INFO] ocpp:OCPP        :: Connector#1: Received SessionStarted
everest-ac-demo-manager-1      | 2024-03-21 04:40:30.144570 [INFO] ocpp:OCPP        :: Logging OCPP messages to html file: /tmp/everest-logs/2024-03-21T04:40:30.120Z-716f191f-f403-4170-81d3-36a39e1ba120/incomplete-ocpp.html
everest-ac-demo-steve-1        | [INFO ] 2024-03-21 04:40:30,270 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp2069500590-32) - [chargeBoxId=cp001, sessionId=c277938a-58ee-87f2-50ca-a76c30aad446] Received: [2,"7dcaeb09-3cf4-4b8b-b3d1-9e01be80ac13","StatusNotification",{"connectorId":1,"errorCode":"NoError","info":"EVConnected","status":"Preparing","timestamp":"2024-03-21T04:40:30.145Z"}]
everest-ac-demo-steve-1        | [INFO ] 2024-03-21 04:40:31,068 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp2069500590-32) - [chargeBoxId=cp001, sessionId=c277938a-58ee-87f2-50ca-a76c30aad446] Sending: [3,"7dcaeb09-3cf4-4b8b-b3d1-9e01be80ac13",{}]
everest-ac-demo-manager-1      | 2024-03-21 04:40:32.343761 [INFO] token_provider_  :: Publishing new dummy token: {"id_token":"DEADBEEF","authorization_type":"RFID","prevalidated":false,"connectors":[1]}
everest-ac-demo-manager-1      | 2024-03-21 04:40:32.410022 [INFO] auth:Auth        :: Received new token: {
everest-ac-demo-manager-1      |     "authorization_type": "RFID",
everest-ac-demo-manager-1      |     "connectors": [
everest-ac-demo-manager-1      |         1
everest-ac-demo-manager-1      |     ],
everest-ac-demo-manager-1      |     "id_token": "DEADBEEF",
everest-ac-demo-manager-1      |     "prevalidated": false
everest-ac-demo-manager-1      | }
everest-ac-demo-steve-1        | [INFO ] 2024-03-21 04:40:32,493 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp2069500590-30) - [chargeBoxId=cp001, sessionId=c277938a-58ee-87f2-50ca-a76c30aad446] Received: [2,"aceb9ead-f3fd-4005-b986-25cf548f83cd","Authorize",{"idTag":"DEADBEEF"}]
everest-ac-demo-steve-1        | [INFO ] 2024-03-21 04:40:34,595 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp2069500590-30) - [chargeBoxId=cp001, sessionId=c277938a-58ee-87f2-50ca-a76c30aad446] Sending: [3,"aceb9ead-f3fd-4005-b986-25cf548f83cd",{"idTagInfo":{"status":"Accepted","expiryDate":"2024-03-21T05:40:34.224Z"}}]
everest-ac-demo-manager-1      | 2024-03-21 04:40:34.694405 [INFO] auth:Auth        :: Providing authorization to connector#1
everest-ac-demo-manager-1      | 2024-03-21 04:40:34.798768 [INFO] auth:Auth        :: Result for token: DEADBEEF: ACCEPTED
everest-ac-demo-manager-1      | 2024-03-21 04:40:34.853435 [INFO] evse_manager_1:  :: EVSE IEC EIM Authorization received
everest-ac-demo-manager-1      | 2024-03-21 04:40:34.861440 [INFO] evse_manager_1:  :: EVSE IEC Transaction Started (0 kWh)
everest-ac-demo-manager-1      | 2024-03-21 04:40:34.867661 [INFO] evse_manager_1:  :: EVSE IEC AC mode, HLC disabled. We are in X1 so we can go directly to nominal PWM.
everest-ac-demo-manager-1      | 2024-03-21 04:40:34.869929 [INFO] evse_manager_1:  :: EVSE IEC Charger state: Wait for Auth->PrepareCharging
everest-ac-demo-manager-1      | 2024-03-21 04:40:34.908662 [INFO] evse_manager_1:  :: EVSE IEC Set PWM On (33.33333432674408%) took 0 ms
everest-ac-demo-manager-1      | 2024-03-21 04:40:34.910518 [INFO] ocpp:OCPP        :: EVSE#1: Received TransactionStarted
everest-ac-demo-steve-1        | [INFO ] 2024-03-21 04:40:34,962 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp2069500590-29) - [chargeBoxId=cp001, sessionId=c277938a-58ee-87f2-50ca-a76c30aad446] Received: [2,"55025cc0-c781-4a52-9f4c-608d2fc6c2bb","StartTransaction",{"connectorId":1,"idTag":"DEADBEEF","meterStart":0,"timestamp":"2024-03-21T04:40:34.854Z"}]
everest-ac-demo-manager-1      | 2024-03-21 04:40:35.336048 [INFO] car_simulator_1  :: { cmd: 'sleep', args: [ 1 ], exec: [Function (anonymous)] }
everest-ac-demo-manager-1      | 2024-03-21 04:40:36.588479 [INFO] car_simulator_1  :: {
everest-ac-demo-manager-1      |   cmd: 'draw_power_regulated',
everest-ac-demo-manager-1      |   args: [ 16, 3 ],
everest-ac-demo-manager-1      |   exec: [Function (anonymous)]
everest-ac-demo-manager-1      | }
everest-ac-demo-manager-1      | 2024-03-21 04:40:36.589821 [INFO] car_simulator_1  :: { cmd: 'sleep', args: [ 36000 ], exec: [Function (anonymous)] }
everest-ac-demo-manager-1      | 2024-03-21 04:40:36.852703 [INFO] evse_manager_1:  ::                                     CAR IEC Event CarRequestedPower
everest-ac-demo-manager-1      | 2024-03-21 04:40:36.863537 [INFO] evse_manager_1:  :: EVSE IEC Charger state: PrepareCharging->Charging
everest-ac-demo-manager-1      | 2024-03-21 04:40:37.119365 [INFO] evse_manager_1:  :: EVSE IEC Event PowerOn
everest-ac-demo-steve-1        | [INFO ] 2024-03-21 04:40:37,964 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp2069500590-29) - [chargeBoxId=cp001, sessionId=c277938a-58ee-87f2-50ca-a76c30aad446] Sending: [3,"55025cc0-c781-4a52-9f4c-608d2fc6c2bb",{"transactionId":1,"idTagInfo":{"status":"Accepted","expiryDate":"2024-03-21T05:40:35.254Z"}}]
everest-ac-demo-steve-1        | [INFO ] 2024-03-21 04:40:38,045 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp2069500590-30) - [chargeBoxId=cp001, sessionId=c277938a-58ee-87f2-50ca-a76c30aad446] Received: [2,"f73fe198-51ff-4fdb-89a5-3fb61a9a880c","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Charging","timestamp":"2024-03-21T04:40:36.869Z"}]
everest-ac-demo-steve-1        | [INFO ] 2024-03-21 04:40:38,334 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger (qtp2069500590-30) - [chargeBoxId=cp001, sessionId=c277938a-58ee-87f2-50ca-a76c30aad446] Sending: [3,"f73fe198-51ff-4fdb-89a5-3fb61a9a880c",{}]
shankari commented 3 months ago

I pulled the changes into a local branch and they are not working for OCPP 1.6J but with a weird error. @activeshadow what error do you see while trying to run OCPP 1.6J?

 ✔ Container everest-ac-demo-steve-1                                                                                                                         Healthy[+] Running 8/8
 ✔ Network everest-ac-demo_default                                                                                                                           Created0.3s
 ✔ Container everest-ac-demo-mqtt-server-1                                                                                                                   Healthy0.3s
 ✔ Container everest-ac-demo-ocpp-db-1                                                                                                                       Healthy0.3s
 ! ocpp-db The requested image's platform (linux/arm64/v8) does not match the detected host platform (linux/amd64/v3) and no specific platform was requested 0.0s
 ✔ Container everest-ac-demo-steve-1                                                                                                                         Healthy[+] Running 8/8
 ✔ Network everest-ac-demo_default                                                                                                                           Created0.3s
 ✔ Container everest-ac-demo-mqtt-server-1                                                                                                                   Healthy0.3s
 ✔ Container everest-ac-demo-ocpp-db-1                                                                                                                       Healthy0.3s
 ! ocpp-db The requested image's platform (linux/arm64/v8) does not match the detected host platform (linux/amd64/v3) and no specific platform was requested 0.0s
 ✔ Container everest-ac-demo-steve-1                                                                                                                         Healthy0.2s
 ✔ Container everest-ac-demo-nodered-1                                                                                                                       Started0.2s
 ✔ Container everest-ac-demo-manager-1                                                                                                                       Healthy0.2s
 ! steve The requested image's platform (linux/arm64) does not match the detected host platform (linux/amd64/v3) and no specific platform was requested      0.0s
canceled
shankari commented 3 months ago

In spite of that error, both steve and occp-db seem to start, until steve has a java error on startup. I have seen this before, probably a memory error given that it happens while putting some data

2024-03-20 22:55:50 # A fatal error has been detected by the Java Runtime Environment:
2024-03-20 22:55:50 #
2024-03-20 22:55:50 #  SIGSEGV (0xb) at pc=0x000000551a0cf444, pid=50, tid=53
2024-03-20 22:55:50 #
2024-03-20 22:55:50 # JRE version: OpenJDK Runtime Environment (11.0.4+11) (build 11.0.4+11)
2024-03-20 22:55:50 # Java VM: OpenJDK 64-Bit Server VM (11.0.4+11, mixed mode, tiered, compressed oops, g1 gc, linux-aarch64)
2024-03-20 22:55:50 # Problematic frame:
2024-03-20 22:55:50 # J 1297 c2 java.util.HashMap.put(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; java.base@11.0.4 (13 bytes) @ 0x000000551a0cf444 [0x000000551a0cf400+0x0000000000000044]
2024-03-20 22:55:50 #
2024-03-20 22:55:50 # No core dump will be written. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
2024-03-20 22:55:50 #
2024-03-20 22:55:50 # An error report file with more information is saved as:
2024-03-20 22:55:50 # /steve/hs_err_pid50.log
2024-03-20 22:55:50 Compiled method (c2)   69504 1297       4       java.util.HashMap::put (13 bytes)
2024-03-20 22:55:50  total in heap  [0x000000551a0cf090,0x000000551a0d0b40] = 6832
2024-03-20 22:55:50  relocation     [0x000000551a0cf208,0x000000551a0cf3c8] = 448
2024-03-20 22:55:50  main code      [0x000000551a0cf400,0x000000551a0d0280] = 3712
2024-03-20 22:55:50  stub code      [0x000000551a0d0280,0x000000551a0d04c0] = 576
2024-03-20 22:55:50  metadata       [0x000000551a0d04c0,0x000000551a0d0560] = 160
2024-03-20 22:55:50  scopes data    [0x000000551a0d0560,0x000000551a0d0888] = 808
2024-03-20 22:55:50  scopes pcs     [0x000000551a0d0888,0x000000551a0d0a18] = 400
2024-03-20 22:55:50  dependencies   [0x000000551a0d0a18,0x000000551a0d0a20] = 8
2024-03-20 22:55:50  handler table  [0x000000551a0d0a20,0x000000551a0d0b28] = 264
2024-03-20 22:55:50  nul chk table  [0x000000551a0d0b28,0x000000551a0d0b40] = 24
2024-03-20 22:55:50 Could not load hsdis-aarch64.so; library not loadable; PrintAssembly is disabled
2024-03-20 22:55:51 #
2024-03-20 22:55:51 # If you would like to submit a bug report, please visit:
2024-03-20 22:55:51 #   http://bugreport.java.com/bugreport/crash.jsp
2024-03-20 22:55:51 #
2024-03-20 22:55:51 qemu: uncaught target signal 6 (Aborted) - core dumped
2024-03-20 22:55:51 /steve/init.sh: line 10:    50 Aborted                 java -jar target/steve.jar
shankari commented 3 months ago

I just tried the same command back to back, it works on main but not on this branch

$ git checkout main
$ docker compose -f docker-compose.ocpp16j.yml up -d
(checked docker logs, no errors)
$ git checkout new_demo_script
$ docker compose -f docker-compose.ocpp16j.yml up -d
(checked docker logs, SIGSEGV)

I don't understand this; there are no changes to the docker-compose.ocpp16j.yml file, so why would switching to this branch change it in any way? I can say, though, that this is 100% reproducible (3/3 times).

@activeshadow what error do you see while running the 1.6J demo? @sahabulh @jhoshiko when you try to run the docker compose on both main and this branch, what do you see?

@activeshadow if this pattern holds (works on main, does not work on git pull https://github.com/activeshadow/everest-demo.git new-demo-script) we might want to consider removing the 1.6J code from this refactor (although I don't know why that would make a difference) so that it can keep working. We are not going to support 1.6J over the long-term and will eventually remove it anyway. It also makes the script easier, since it does not have to add checks for 1.6 versus 201.

shankari commented 3 months ago

Actually, I take that back. After testing ~ 10 times on main, I got the same SIGSEGV error twice. So this is probably not a regression. Will try it ~ 10 times on the branch tomorrow and see if it succeeds even once If it does succeed, this is probably not worth spending significant time on since OCPP 1.6J is now obsolete anyway

shankari commented 3 months ago

Ok, after trying ~ 5 times on the new branch, I got a single success.

So:

  1. This is an intermittent error that happens on both branches
  2. It appears to happen more frequently in the new branch than the old one
  3. We do not have the time or resources to figure out why this happens since:
    • OCPP 1.6J is obsolete in the US
    • even if a network wanted to use OCPP 1.6J, they would likely not want to use Steve, which is GPLed

@activeshadow please update the README with the instructions for the new method and flag that the 1.6J demo will fail intermittently, and we will not fix it

I will then merge.

activeshadow commented 3 months ago

@shankari I should be able to update the README tomorrow.

activeshadow commented 3 months ago

@shankari README has been updated and I've tested the one-liners where the script is curled and piped to bash.

sahabulh commented 3 months ago

@sahabulh just calling you out here for your situational awareness. Feel free to review as well!

@activeshadow , Sorry! I am really busy with my PhD study. But I will test this tonight.

shankari commented 3 months ago

@sahabulh @jhoshiko can you please test these scripts as well? We can address any issues in a subsequent PR

sahabulh commented 3 months ago

@sahabulh @jhoshiko can you please test these scripts as well? We can address any issues in a subsequent PR

Yeah, I will do it tonight.

jhoshiko commented 3 months ago

can you please test these scripts as well? We can address any issues in a subsequent PR

Ok, I've tested the script with all 3 security profiles and everything works on my end. Similar to both of you, I also tested 1.6j with the script and was only able to get it to work once.

sahabulh commented 3 months ago

@shankari Same thing for me. OCPP 2.0.1 all profiles work fine but 0CPP 1.6j exiting with the already reported error.