EVerest / everest-demo

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

Build and run custom version of EVerest on the uMWC #51

Closed shankari closed 1 month ago

shankari commented 6 months ago

The EVerest project has open hardware as well https://everest.github.io/nightly/hardware/pionix_belay_box.html which is available as a kit from Pionix. Pionix also sells the uMWC (https://shop.pionix.com/products/umwc-micro-mega-watt-charger). This is is a non-open device in a housing that shares some hardware with the Belay Box although it has a different power module that is limited to 1W output.

In this issue, we will track the steps to run a custom build of EVerest on the uMWC so that we can perform HIL testing.

@faizanmir21 The instructions are here: https://everest.github.io/nightly/hardware/pionix_belay_box.html#developing-with-everest-and-belaybox

They are for the Belay Box, but I'm hoping that they will apply to the uMWC as well. If not, we can ask the community for help.

My suggested steps are:

  1. check everest-dev.service and verify that it starts the dev build from /mnt/user_data/opt/everest
  2. Install a dev build from the latest stable release (2024.3.0) https://github.com/EVerest/everest-core/releases/tag/2024.3.0
    • We already have everest builds in the docker containers. So you can run the manager docker container and use it as the base to cross-compile. To get a shell, you can use:
    • one of the demo scripts and then docker exec -it ....manager /bin/bash OR
    • docker run -it ghcr.io/everest/everest-demo/manager:0.0.16 /bin/bash
  3. Then rsync it over and try to boot up!

@drmrd @couryrr-afs @wjmp for visibility

shankari commented 3 months ago

/mnt/user_data/opt/everest != /opt/everest. You are running the pre-installed manager from /opt/everest It is also not clear where you are running this from ./ just indicates "current directory"

faizanmir21 commented 3 months ago

I was in /mnt/user_data directory but like you said its not the same. Starting the manager again

sudo mnt/user_data/opt/everest/bin/manager --conf /mnt/user_data/opt/everest/etc/everest/config-sil-ocpp201-pnc.yaml

Ran into this error

2024-08-16 06:18:49.065844 [INFO] ocpp:OCPP201     :: Successfully retrieved Device Model from DeviceModelStorage
2024-08-16 06:18:49.066833 [ERRO] ocpp:OCPP201    void ocpp::v201::DeviceModel::check_integrity(const std::map<int, int>&) :: Integrity check in Device Model storage failed:Number of EVSE configured in device model is incompatible with number of configured EVSEs of the ChargePoint: 2: 1
terminate called after throwing an instance of 'ocpp::v201::DeviceModelStorageError'
  what():  Number of EVSE configured in device model is incompatible with number of configured EVSEs of the ChargePoint: 2: 1
2024-08-16 06:18:49.455190 [INFO] evse_manager_1:  :: Ignoring BSP Event, BSP is not enabled yet.

Has 2 EVSE

shankari commented 3 months ago

@faizanmir21 check the prior comments here and in related demo issues. you need to edit the device_model.db or copy over one from the repo. Again, everything that I did to get things to work is written down.

You also need to be careful about relative versus absolute paths

mnt/user_data/opt/everest/bin/manager is a relative path /mnt/user_data/opt/everest/etc/everest/config-sil-ocpp201-pnc.yaml is an absolute path

mixing and matching them is a recipe for disaster.

faizanmir21 commented 3 months ago

Got it ! Removed the second evse from the database: sqlite3 mnt/user_data/opt/everest/share/everest/modules/OCPP201/device_model_storage.db

Now I am seeing this, it says ERROR but it looks like a log indicating the max AC current was set to 32amps, correct me if I am wrong here.

2024-08-19 20:07:17.114787 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 0.000000, we get 0.000000

2024-08-19 20:07:17.117362 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 32.000000, we get 32.000000

Another error I am seeing is, it is try to connect to a local OCPP server.

2024-08-19 20:07:20.448225 [ERRO] ocpp:OCPP201    int ocpp::WebsocketTlsTPM::process_callback(void*, int, void*, void*, size_t) :: CLIENT_CONNECTION_ERROR: conn fail: 113
2024-08-19 20:07:20.448566 [ERRO] ocpp:OCPP201    void ocpp::WebsocketTlsTPM::on_conn_fail() :: OCPP client connection to server failed
2024-08-19 20:07:20.448977 [INFO] ocpp:OCPP201     :: Reconnecting in: 3000ms, attempt: 1

I see you used this to reset the host with CSMS server at "ocppCsmsUrl": "ws://169.254.223.121/ws/cp001"

sqlite> update variable_attribute set "value"='[{"configurationSlot": 1, "connectionData": {"messageTimeout": 30, "ocppCsmsUrl": "ws://169.254.223.121/ws/cp001", "ocppInterface": "Wired0", "ocppTransport": "JSON", "ocppVersion": "OCPP20", "securityProfile": 1}}]' where id=161

I am seeing this to setup an CSMS server on GitHub repo.

🚨 Basic and ISO 15118-2 AC Charging with OCPP 2.0.1 CSMS (MaEVe Security Profile 1) ⚑: curl https://raw.githubusercontent.com/everest/everest-demo/main/demo-iso15118-2-ac-plus-ocpp.sh | bash -s -- -1
🚨 Basic and ISO 15118-2 AC Charging with OCPP 2.0.1 CSMS (MaEVe Security Profile 2) ⚑: curl https://raw.githubusercontent.com/everest/everest-demo/main/demo-iso15118-2-ac-plus-ocpp.sh | bash -s -- -2
🚨 Basic and ISO 15118-2 AC Charging with OCPP 2.0.1 CSMS (MaEVe Security Profile 3) ⚑: curl https://raw.githubusercontent.com/everest/everest-demo/main/demo-iso15118-2-ac-plus-ocpp.sh | bash -s -- -3
faizanmir21 commented 3 months ago

Setup CSMS from the charin repo using: bash demo-iso15118-2-ac-plus-ocpp.sh -r $(pwd) -3

Updated the device_model_storage.db and changed the CsmsUrl to 192.168.65.1/ws/cp001

sqlite> update variable_attribute set "value"='[{"configurationSlot": 1, "connectionData": {"messageTimeout": 30, "ocppCsmsUrl": "ws://169.254.223.121/ws/cp001", "ocppInterface": "Wired0", "ocppTransport": "JSON", "ocppVersion": "OCPP20", "securityProfile": 1}}]' where id=161 

Getting this output

2024-08-21 07:25:46.017771 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 32.000000, we get 32.000000
2024-08-21 07:25:46.711014 [INFO] ocpp:OCPP201     :: Using network iface: 
2024-08-21 07:25:46.712208 [INFO] ocpp:OCPP201     :: LWS connect with info port: [80] address: [192.168.65.1] path: [/ws/cp001] protocol: [ocpp2.0.1]
2024-08-21 07:25:47.122021 [INFO] energy_manager:  ::                                NO TRADE 
2024-08-21 07:25:47.123399 [INFO] energy_manager:  :: Sending enfored limits (import) to :evse_manager_1 {
    "ac_max_current_A": 32.0
}
2024-08-21 07:25:47.125302 [INFO] energy_manager:  :: returning optimized values vector of length 1
2024-08-21 07:25:47.126106 [INFO] energy_manager:  :: evse_manager_1 Enforce limits 32A -9999W 

Seems to be connected to the CSMS server. Error output showing the max AC current was set to 32A and we are getting 32A.

shankari commented 3 months ago

@faizanmir21 the logs are marked as ERROR but only so that I could see the logs without changing the log level. Those logs should actually be at the DEBUG/INFO level.

I am pretty sure I put that into the issue tracking the software changes: https://github.com/EVerest/everest-demo/issues/44 but I am not 100% sure that I did

faizanmir21 commented 3 months ago

Updated the config to enable uMWC BSP

bsp:
  - module_id: yeti_driver_1
     implementation_id: board_support

Defined yeti_driver_1 as

  yeti_driver:
   module: MicroMegaWattBSP
   config_module:
    baud_rate: 115200
    reset_gpio: 27
    serial_port: /dev/serial0

configured slac to also be real and not a simulator and removed the car simulator

  slac:
    module: EvseSlac
    config_implementation:
     main:
      device: eth1

Loading the updated config file

2024-08-29 08:07:06.896778 [INFO] ocpp:OCPP201     :: Module ocpp initialized [3836ms]
2024-08-29 08:07:07.038824 [INFO] evse_manager_1:  :: Module evse_manager_1 initialized [4178ms]
2024-08-29 08:07:08.408035 [INFO] manager          :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [6759ms] πŸš™πŸš™πŸš™
2024-08-29 08:07:08.418580 [WARN] ocpp:OCPP201    void module::OCPP201::ready() :: Launching timer for calling set_external_limits function
sh: 1: echo: echo: I/O error
terminate called after throwing an instance of 'std::out_of_range'
  what():  No known string conversion for provided enum of type Connector_type
2024-08-29 08:07:08.436836 [INFO] energy_manager:  :: returning optimized values vector of length 0
2024-08-29 08:07:08.453225 [INFO] slac:EvseSlac    :: Starting the SLAC state machine
2024-08-29 08:07:08.454844 [INFO] slac:EvseSlac    :: Qualcomm PLC Device Attributes:
  HW Platform: QCA7000
  SW Platform: MAC
  Firmware: 
  Build date: 1.2.5-0
  ZC signal: Missing
  Line frequency: 50Hz
shankari commented 3 months ago

@faizanmir21 it is not clear what is happening here. Is the service crashing or has it started up successfully?

faizanmir21 commented 3 months ago

No, it crashes as I load the config.

2024-09-04 20:24:08.069931 [INFO] manager          ::   ________      __                _   
2024-09-04 20:24:08.070850 [INFO] manager          ::  |  ____\ \    / /               | |  
2024-09-04 20:24:08.071034 [INFO] manager          ::  | |__   \ \  / /__ _ __ ___  ___| |_ 
2024-09-04 20:24:08.071173 [INFO] manager          ::  |  __|   \ \/ / _ \ '__/ _ \/ __| __|
2024-09-04 20:24:08.071308 [INFO] manager          ::  | |____   \  /  __/ | |  __/\__ \ |_ 
2024-09-04 20:24:08.071436 [INFO] manager          ::  |______|   \/ \___|_|  \___||___/\__|
2024-09-04 20:24:08.071563 [INFO] manager          :: 
2024-09-04 20:24:08.071681 [INFO] manager          :: Using MQTT broker localhost:1883
2024-09-04 20:24:08.100978 [INFO] everest_ctrl     :: Launching controller service on port 8849
2024-09-04 20:24:08.165953 [INFO] manager          :: Loading config file at: /mnt/user_data/opt/everest/etc/everest/user-config/config-sil-ocpp201-pnc.yaml
2024-09-04 20:24:09.096893 [INFO] manager          :: Config loading completed in 1019ms
2024-09-04 20:24:12.905283 [INFO] system:System    :: Module system initialized [3555ms]
2024-09-04 20:24:12.921525 [INFO] energy_manager:  :: Module energy_manager initialized [3733ms]
2024-09-04 20:24:12.985645 [INFO] grid_connection  :: Module grid_connection_point initialized [3684ms]
2024-09-04 20:24:13.075770 [INFO] slac:EvseSlac    :: Module slac initialized [3721ms]
2024-09-04 20:24:13.103779 [INFO] api:API          :: Module api initialized [3932ms]
2024-09-04 20:24:13.114732 [INFO] token_provider_  :: Module token_provider_1 initialized [3746ms]
2024-09-04 20:24:13.125286 [INFO] auth:Auth        :: Module auth initialized [3957ms]
2024-09-04 20:24:13.197236 [INFO] ocpp:OCPP201     :: Module ocpp initialized [3695ms]
2024-09-04 20:24:13.215439 [INFO] evse_security:E  :: Module evse_security initialized [3874ms]
2024-09-04 20:24:13.232503 [INFO] yeti_driver_1:M  :: Module yeti_driver_1 initialized [3792ms]

2024-09-04 20:24:13.252601 [INFO] iso15118_charge  :: TCP server on wlan0 is listening on port [fe80::f657:d2a1:20d:b660%3]:61341

2024-09-04 20:24:13.253187 [INFO] iso15118_charge  :: TLS server on wlan0 is listening on port [fe80::f657:d2a1:20d:b660%3]:64109

2024-09-04 20:24:13.253385 [INFO] iso15118_charge  :: SDP socket setup succeeded
2024-09-04 20:24:13.254546 [INFO] iso15118_charge  :: Module iso15118_charger initialized [3910ms]
2024-09-04 20:24:13.471189 [INFO] evse_manager_1:  :: Module evse_manager_1 initialized [4200ms]
2024-09-04 20:24:14.913976 [INFO] manager          :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [6868ms] πŸš™πŸš™πŸš™
2024-09-04 20:24:14.918959 [WARN] ocpp:OCPP201    void module::OCPP201::ready() :: Launching timer for calling set_external_limits function
sh: 1: echo: echo: I/O error
terminate called after throwing an instance of 'std::out_of_range'
  what():  No known string conversion for provided enum of type Connector_type
2024-09-04 20:24:14.950648 [INFO] energy_manager:  :: returning optimized values vector of length 0
2024-09-04 20:24:14.990884 [INFO] slac:EvseSlac    :: Starting the SLAC state machine
2024-09-04 20:24:14.992738 [INFO] slac:EvseSlac    :: Qualcomm PLC Device Attributes:
  HW Platform: QCA7000
  SW Platform: MAC
  Firmware: 
  Build date: 1.2.5-0
  ZC signal: Missing
  Line frequency: 50Hz
2024-09-04 20:24:14.995363 [INFO] ocpp:OCPP201     :: Established connection to database: "/mnt/user_data/opt/everest/share/everest/modules/OCPP201/device_model_storage.db"
2024-09-04 20:24:14.995811 [INFO] ocpp:OCPP201     :: Established connection to device model database successfully: "/mnt/user_data/opt/everest/share/everest/modules/OCPP201/device_model_storage.db"
2024-09-04 20:24:15.057240 [INFO] ocpp:OCPP201     :: Successfully retrieved Device Model from DeviceModelStorage
2024-09-04 20:24:15.058554 [INFO] ocpp:OCPP201     :: Established connection to database: "/tmp/ocpp201/cp.db"
2024-09-04 20:24:15.059189 [INFO] ocpp:OCPP201     :: Target version: 2, current version: 2
2024-09-04 20:24:15.059504 [INFO] ocpp:OCPP201     :: No migrations to apply since versions match
2024-09-04 20:24:15.059804 [INFO] ocpp:OCPP201     :: Successfully closed database: "/tmp/ocpp201/cp.db"
2024-09-04 20:24:15.060318 [INFO] ocpp:OCPP201     :: Established connection to database: "/tmp/ocpp201/cp.db"
2024-09-04 20:24:15.066478 [INFO] ocpp:OCPP201     :: Logging OCPP messages to log file: /tmp/everest_ocpp_logs/2024-09-04T19:24:15.066Z.log
2024-09-04 20:24:15.066979 [INFO] ocpp:OCPP201     :: Logging OCPP messages to html file: /tmp/everest_ocpp_logs/2024-09-04T19:24:15.066Z.html
2024-09-04 20:24:15.067368 [INFO] ocpp:OCPP201     :: Logging SecurityEvents to file
2024-09-04 20:24:15.093313 [INFO] slac:EvseSlac    :: Entered Reset state
2024-09-04 20:24:15.093701 [INFO] slac:EvseSlac    :: New NMK key: 39:41:5A:35:47:4E:31:43:48:54:4E:37:44:4A:31:4F
2024-09-04 20:24:15.094409 [INFO] slac:EvseSlac    :: Received CM_SET_KEY_CNF
2024-09-04 20:24:15.094907 [INFO] slac:EvseSlac    :: Entered Idle state
2024-09-04 20:24:15.182387 [INFO] ocpp:OCPP201     :: TxStartPoints from device model: PowerPathClosed
2024-09-04 20:24:15.183356 [INFO] ocpp:OCPP201     :: TxStopPoints from device model: EVConnected,Authorized
2024-09-04 20:24:15.810714 [CRIT] manager         int boot(const boost::program_options::variables_map&) :: Module yeti_driver_1 (pid: 2609) exited with status: 134. Terminating all modules.
2024-09-04 20:24:15.812087 [INFO] manager          :: SIGTERM of child: api (pid: 2597) succeeded.
2024-09-04 20:24:15.812280 [INFO] manager          :: SIGTERM of child: auth (pid: 2598) succeeded.
2024-09-04 20:24:15.812390 [INFO] manager          :: SIGTERM of child: energy_manager (pid: 2599) succeeded.
2024-09-04 20:24:15.812609 [INFO] manager          :: SIGTERM of child: evse_manager_1 (pid: 2600) succeeded.
2024-09-04 20:24:15.812743 [INFO] manager          :: SIGTERM of child: evse_security (pid: 2601) succeeded.
2024-09-04 20:24:15.812856 [INFO] manager          :: SIGTERM of child: grid_connection_point (pid: 2602) succeeded.
2024-09-04 20:24:15.812961 [INFO] manager          :: SIGTERM of child: iso15118_car (pid: 2603) succeeded.
2024-09-04 20:24:15.813063 [INFO] manager          :: SIGTERM of child: iso15118_charger (pid: 2604) succeeded.
2024-09-04 20:24:15.813198 [INFO] manager          :: SIGTERM of child: ocpp (pid: 2605) succeeded.
2024-09-04 20:24:15.813300 [INFO] manager          :: SIGTERM of child: slac (pid: 2606) succeeded.
2024-09-04 20:24:15.821406 [INFO] manager          :: SIGTERM of child: system (pid: 2607) succeeded.
2024-09-04 20:24:15.821779 [INFO] manager          :: SIGTERM of child: token_provider_1 (pid: 2608) succeeded.
2024-09-04 20:24:15.822012 [CRIT] manager         int boot(const boost::program_options::variables_map&) :: Exiting manager.

seems to be calling calling set_external_limitsfunction

faizanmir21 commented 3 months ago

Also noticed this message on CSMS

2024-09-04 19:27:49.486710 [ERRO] ocpp:OCPP201    void ocpp::v201::ChargePoint::handle_message(const ocpp::EnhancedMessage<ocpp::v201::MessageType>&) :: json_message called: [3,"7be3e28a-7247-4e47-9fca-7c4faa43c486",{"currentTime":"2024-09-04T19:27:49Z"}]

The timestamp seems to be off between the two

faizanmir21 commented 2 months ago

The yaml file for Evse Manager module does not call set_external_limits function. However the the yaml file in interface dir has a set_external_limits function. Located at: mnt/user_data/opt/everest/share/everest/interfaces/evse_manager.yaml

  set_external_limits:
    description: Set additional external energy flow limits at this node.
    arguments:
      value:
        description: UUID of node that this limit applies to
        type: object
        $ref: /energy#/ExternalLimits

In the config file, the grid_connection_point uses EnergyNode module as:

  grid_connection_point:
    module: EnergyNode
    config_module:
      fuse_limit_A: 40.0
      phase_count: 3

In EnergyNode module located at mnt/user_data/opt/everest/libexec/everest/modules/EnergyNode/manifest.yaml It provides external_energy_limits as output:

provides:
  energy_grid:
    description: This is the chain interface to build the energy supply tree
    interface: energy
  external_limits:
    description: Additional external limits can be set via this interface.
    interface: external_energy_limits

and there is a external_energy_limits.yaml file located at mnt/user_data/opt/everest/share/everest/interfaces/external_energy_limits.yaml which contains set_external_limits function.

description: >-
  This interface allows to limit energy flow at a specific node of the energy tree from the outside (e.g. from ocpp).
cmds:
  set_external_limits:
    description: Set additional external energy flow limits at this node.
    arguments:
      value:
        description: External limits object
        type: object
        $ref: /energy#/ExternalLimits
vars:
  enforced_limits:
    description: Enforced limits for this node (coming from the EnergyManager)
    type: object
    $ref: /energy#/EnforcedLimits

this says it allows to limit energy flow at a node from outside (e.g ocpp) Then I looked at the OCPP module at mnt/user_data/opt/everest/libexec/everest/modules/OCPP/manifest.yaml which is for OCPP 1.6 and found a required connector_zero_sink using external_energy_limits interface , shown below

requires:
  evse_manager:
    interface: evse_manager
    min_connections: 1
    max_connections: 128
  connector_zero_sink:
    interface: external_energy_limits
    min_connections: 0
    max_connections: 1

However, this variable is not defined in OCPP201 module which we are using in our config.

faizanmir21 commented 2 months ago

Removed OCPP module and getting this error on Connector_types

2024-09-17 01:56:16.177368 [INFO] evse_manager_1:  :: Module evse_manager_1 initialized [3788ms]
2024-09-17 01:56:17.634769 [INFO] manager          :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [6372ms] πŸš™πŸš™πŸš™
sh: 1: echo: echo: I/O error
terminate called after throwing an instance of 'std::out_of_range'
  what():  No known string conversion for provided enum of type Connector_type
2024-09-17 01:56:17.662212 [INFO] energy_manager:  :: returning optimized values vector of length 0

Connector_types seems to be removed from modules/EvseManager/manifest.yaml as shown here and is defined in everest-core/types/evse_board_support.yaml here

connector_type:string <required>
Type of charging connector available at this EVSE
enum:
- IEC62196Type2Cable
- IEC62196Type2Socket

The commit says Yeti and umwc driver will need MCU firmware updates that will come soon Do we need to update the firmware ?

Everest documentation says to stop everest before updating firmware

systemctl stop basecamp
yeti_fwupdate /dev/serial0 /usr/share/everest/modules/YetiDriver/firmware/yetiR1_2.1_firmware.bin
shankari commented 2 months ago

@faizanmir21 I updated the firmware see comments around https://github.com/EVerest/everest-demo/issues/51#issuecomment-2167266067

I was able to start everest after the firmware update. If the firmware update didn't "stick", you should be able to run the old EVerest version.

Regardless of the firmware version, you should be able to run some version of EVerest

corneliusclaussen commented 2 months ago

With the new yocto image for umwc, this works the same way as for the belaybox described here under "Cross compile":

https://everest.github.io/nightly/hardware/pionix_belay_box.html#belaybox-use-cases

New everest versions will not work on the deprecated debian image.

Abby-Wheelis commented 2 months ago

Starting to work on this today, so far still seem to be stuck here: No known string conversion for provided enum of type Connector_type which is thrown by evse_board_support. Looking back through the discussion, I attempted to run the "old" everest with

sudo /opt/everest/bin/manager --conf /opt/everest/conf/3_config-ac-iso2.yaml everest@umwcdbde:~ $ sudo /opt/everest/bin/manager --conf /opt/everest/conf/3_config-ac-iso2.yaml sudo: unable to resolve host umwcdbde: Name or service not known 2024-10-02 22:42:14.413643 [INFO] manager :: ________ __ _ 2024-10-02 22:42:14.414286 [INFO] manager :: | ____\ \ / / | | 2024-10-02 22:42:14.414414 [INFO] manager :: | |__ \ \ / /__ _ __ ___ ___| |_ 2024-10-02 22:42:14.414518 [INFO] manager :: | __| \ \/ / _ \ '__/ _ \/ __| __| 2024-10-02 22:42:14.414615 [INFO] manager :: | |____ \ / __/ | | __/\__ \ |_ 2024-10-02 22:42:14.414713 [INFO] manager :: |______| \/ \___|_| \___||___/\__| 2024-10-02 22:42:14.414808 [INFO] manager :: 2024-10-02 22:42:14.414889 [INFO] manager :: Using MQTT broker localhost:1883 2024-10-02 22:42:14.414988 [INFO] manager :: Telemetry enabled 2024-10-02 22:42:14.486460 [INFO] manager :: Loading config file at: /opt/everest/conf/3_config-ac-iso2.yaml 2024-10-02 22:42:17.431351 [INFO] manager :: - Types loaded in [151ms] 2024-10-02 22:42:17.431542 [INFO] manager :: - Types validated [2759ms] 2024-10-02 22:42:17.437358 [INFO] manager :: - Errors loaded in [1ms] 2024-10-02 22:42:17.437487 [INFO] manager :: - Errors validated [4ms] 2024-10-02 22:42:18.250601 [INFO] manager :: Config loading completed in 3835ms 2024-10-02 22:42:18.313202 [INFO] everest_ctrl :: Launching controller service on port 8849 2024-10-02 22:42:21.709806 [INFO] persistent_stor :: Module persistent_store initialized [3145ms] 2024-10-02 22:42:21.753343 [INFO] packet_sniffer: :: Module packet_sniffer initialized [3194ms] 2024-10-02 22:42:21.984886 [INFO] energy_manager: :: Module energy_manager initialized [3524ms] 2024-10-02 22:42:22.026641 [INFO] setup:Setup :: Module setup initialized [3312ms] 2024-10-02 22:42:22.166415 [INFO] auth:Auth :: Module auth initialized [3703ms] 2024-10-02 22:42:22.306025 [INFO] iso15118_charge :: TCP server on eth1 is listening on port [fe80::643f:6c99:6fd9:ecac%5]:61341 2024-10-02 22:42:22.306642 [INFO] iso15118_charge :: SDP socket setup succeeded 2024-10-02 22:42:22.307510 [INFO] iso15118_charge :: Module iso15118_charger initialized [3704ms] 2024-10-02 22:42:22.416906 [INFO] grid_connection :: Module grid_connection_point initialized [3907ms] 2024-10-02 22:42:22.466155 [INFO] slac:EvseSlac :: Module slac initialized [3802ms] 2024-10-02 22:42:22.563640 [INFO] yeti_driver:Mic :: Module yeti_driver initialized [3566ms] 2024-10-02 22:42:22.581408 [INFO] api:API :: Module api initialized [4156ms] 2024-10-02 22:42:22.607873 [INFO] security:EvseSe :: Module security initialized [3990ms] 2024-10-02 22:42:22.700426 [INFO] evse_manager:Ev :: Module evse_manager initialized [4143ms] 2024-10-02 22:42:22.997871 [INFO] manager :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [8612ms] πŸš™πŸš™πŸš™ sh: 1: echo: echo: I/O error 2024-10-02 22:42:23.135580 [INFO] slac:EvseSlac :: EvseSlac: Starting the SLAC state machine 2024-10-02 22:42:23.135749 [INFO] slac:EvseSlac :: EvseSlac: Entered Reset state 2024-10-02 22:42:23.135956 [INFO] slac:EvseSlac :: EvseSlac: New NMK key: 46:36:52:49:41:59:5A:53:51:5A:34:4F:30:30:54:4B 2024-10-02 22:42:23.136611 [INFO] slac:EvseSlac :: EvseSlac: Received CM_SET_KEY_CNF 2024-10-02 22:42:23.137135 [INFO] slac:EvseSlac :: EvseSlac: Entered Idle state 2024-10-02 22:42:24.101848 [ERRO] yeti_driver:Mic void module::MicroMegaWattBSP::ready() :: uMWC reset not successful. terminate called after throwing an instance of 'boost::wrapexcept' what(): uMWC reset not successful. 2024-10-02 22:42:25.035466 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Module yeti_driver (pid: 5646) exited with status: 134. Terminating all modules. 2024-10-02 22:42:25.036773 [INFO] manager :: SIGTERM of child: api (pid: 5622) succeeded. 2024-10-02 22:42:25.037182 [INFO] manager :: SIGTERM of child: auth (pid: 5623) succeeded. 2024-10-02 22:42:25.037411 [INFO] manager :: SIGTERM of child: energy_manager (pid: 5625) succeeded. 2024-10-02 22:42:25.038379 [INFO] manager :: SIGTERM of child: evse_manager (pid: 5626) succeeded. 2024-10-02 22:42:25.038750 [INFO] manager :: SIGTERM of child: grid_connection_point (pid: 5628) succeeded. 2024-10-02 22:42:25.038931 [INFO] manager :: SIGTERM of child: imd (pid: 5630) succeeded. 2024-10-02 22:42:25.039314 [INFO] manager :: SIGTERM of child: iso15118_charger (pid: 5631) succeeded. 2024-10-02 22:42:25.039707 [INFO] manager :: SIGTERM of child: packet_sniffer (pid: 5632) succeeded. 2024-10-02 22:42:25.040025 [INFO] manager :: SIGTERM of child: persistent_store (pid: 5638) succeeded. 2024-10-02 22:42:25.040391 [INFO] manager :: SIGTERM of child: security (pid: 5639) succeeded. 2024-10-02 22:42:25.040885 [INFO] manager :: SIGTERM of child: setup (pid: 5641) succeeded. 2024-10-02 22:42:25.041138 [INFO] manager :: SIGTERM of child: slac (pid: 5642) succeeded. 2024-10-02 22:42:25.041270 [INFO] manager :: SIGTERM of child: token_provider_1 (pid: 5643) succeeded. 2024-10-02 22:42:25.041378 [INFO] manager :: SIGTERM of child: token_validator (pid: 5645) succeeded. 2024-10-02 22:42:25.041477 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Exiting manager.

The yeti_driver is exiting over an error, causing all modules to terminate

2024-10-02 22:42:24.101848 [ERRO] yeti_driver:Mic void module::MicroMegaWattBSP::ready() :: uMWC reset not successful.
terminate called after throwing an instance of 'boost::wrapexcept<Everest::EverestInternalError>'
  what():  uMWC reset not successful.
2024-10-02 22:42:25.035466 [CRIT] manager         int boot(const boost::program_options::variables_map&) :: Module yeti_driver (pid: 5646) exited with status: 134. Terminating all modules.

Seeing if any of the config files will work:

Ok, clearly need to investigate what could be causing this error - it is the same @shankari encountered after she "Hardcoded and rebuilt" to recover from the connector type error.

That occurance was with the "new" everest, however, and this is the original version ...

It looks like updating the firmware ./umwc_fwupdate /dev/serial0 ../share/everest/modules/YetiDriver/firmware/yetiR1_2.1_firmware.bin might have solved the connector type error, but might have caused this secondary error, so I'm not sure that's the solution.

The other solution to the connector type error seems to have been "hardcode and rebuild" but I'm not sure I understand the codebase well enough yet to know exactly what to change. Maybe I need to start with running this on my computer, then might know enough to get it working on the hardware.

shankari commented 2 months ago

@Abby-Wheelis the firmware has been updated, so I would not expect the older version of EVerest to work. To get the older version to work, you would need to downgrade the firmware, and you would need to get the instructions for that from Pionix. I upgraded the firmware on a two hour long call with a Pionix engineer in which he had to get answers from other people in his team. Neither of us wrote down the steps.

From my notes, I believe that the uMWC reset error is due to the firmware incompatibility.

The connector_type issue is a C++ code issue.

Given that we are going to move to the Yocto version anyway if we can't get this to work, I would suggest hardcoding the value (caps.connector_type = types::evse_board_support::Connector_type::IEC62196Type2Cable;) found in modules/YetiDriver/board_support/evse_board_supportImpl.cpp into modules/MicroMegaWattBSP/board_support/evse_board_supportImpl.cpp

Note that you can should also be able to read the firmware version from the serial port https://github.com/EVerest/everest-demo/issues/51#issuecomment-2167816099 https://github.com/EVerest/everest-demo/issues/51#issuecomment-2167831379 and verify that it has been updated (aka is not 2fcb731e)

Abby-Wheelis commented 2 months ago

Given that we are going to move to the Yocto version anyway if we can't get this to work, I would suggest hardcoding the value (caps.connector_type = types::evse_board_support::Connector_type::IEC62196Type2Cable;) found in modules/YetiDriver/board_support/evse_board_supportImpl.cpp into modules/MicroMegaWattBSP/board_support/evse_board_supportImpl.cpp

I see these files in the everest-core repo, but I have not found them in the directories on the hardware ... should I be editing and rebuilding on my laptop and then push it back over to the device?

Note that you can should also be able to read the firmware version from the serial port

I am not sure how to interpret this, but it is different than what you saw

7AC?7A??@?? ????(21.0=BE
??7A+?7A??@@???Σ‹?(21.0=BE@HP?????
??7Aw?7A??@??T?3???(21.0=BEHP?(9??
+?7A?7A??`??????(21.0=BE   ?@HP1???
z?7Aw?7A??@??GpI???(21.0=BEP?N@?
??7A??7A??@?????(21.0=BE   ?@HP????
w?7A??7A??`????Κ“?(21.0=BE@HP?0???
_?7A??7A??@??X???(21.0=BE?@HP?OΘ€?
??7A?7A??@@Ώ????(21.0=BE ?@HPVΞ”1?
shankari commented 2 months ago

I am not sure how to interpret this, but it is different than what you saw

Yup! So it is running the new firmware. I think I still have a copy of the new firmware sitting around somewhere if you want to check the version, but I don't think that is interesting now.

I see these files in the everest-core repo, but I have not found them in the directories on the hardware ... should I be editing and rebuilding on my laptop and then push it back over to the device?

Yes! You should spin up the cross-compile (https://en.wikipedia.org/wiki/Cross_compiler) image (https://github.com/US-JOET/everest-demo/pkgs/container/everest-demo%2Fmanager/255301468?tag=cross-compile-charin-e2e-demo), edit, rebuild and then copy over as in https://github.com/EVerest/everest-demo/issues/51#issuecomment-2167176765

Your "development host" is the docker container with the cross-compile chain set up. Your "embedded system" is the uMWC

Abby-Wheelis commented 2 months ago

Progress so far:

Got error:

2024-10-03 18:53:40.210362 [ERRO] manager         void Everest::Config::load_and_validate_manifest(const string&, const json&) :: Config entry 'connector_id' for module config not defined in manifest of module '"MicroMegaWattBSP"'!

Initial guess is config incompatibility ... let's see what I can work out ...

So now I'm thinking it has something to do with the way the config is expected to be formatted vs what is actually needed ... Since the connector_id is both a "mandatory config entry 'connector_id' for module config in module "EvseManager"" and "not defined in manifest of module '"EvseManager"'!"

My next idea to try - can I either make it not mandatory or define it in the manifest?

shankari commented 2 months ago

@Abby-Wheelis note that the original error was not defined in manifest of module '"MicroMegaWattBSP"'! but the second one is Missing mandatory config entry 'connector_id' for module config in module "EvseManager"

They are two separate modules with different expected configurations (as you may remember from the high level overview).

Abby-Wheelis commented 2 months ago

They are two separate modules

Ah, ok, I saw that it was the same parameter and overlooked the part where it was two different modules. I am out of time to work on this today, but will investigate more tomorrow, maybe it is just an issue with the config

Abby-Wheelis commented 2 months ago

Made some required updates to the config today with help from @faizanmir21, but still getting an error about the Connector_type:

sudo /mnt/user_data/oct3/everest/bin/manager --conf /mnt/user_data/oct3/everest/etc/everest/user-config/config-sil-ocpp201-pnc-new.yaml 
terminate called after throwing an instance of 'std::out_of_range'
  what():  No known string conversion for provided enum of type Connector_type

I'm sure I changed the line, so either 1) I built wrong, or 2) there is some other error. I wish I could figure out where it is trying to convert to a string, but there is no stacktrace.

shankari commented 2 months ago

I'm sure I changed the line, so either 1) I built wrong, or 2) there is some other error. I wish I could figure out where it is trying to convert to a string, but there is no stacktrace.

Can you rebuild with a new log statement to see whether the newly built version is what is being launched? You can also search for where the config is being parsed in the module and add additional logs there

EDIT: Also, what were the changes that you made? I remember @faizanmir21 running into this error earlier https://github.com/EVerest/everest-demo/issues/51#issuecomment-2316886486 but it doesn't seem like we resolved it?

Here's a PR which changed some similar messages; maybe that is where we can find this error as well? https://github.com/EVerest/everest-framework/pull/194

Abby-Wheelis commented 2 months ago

Can you rebuild with a new log statement to see whether the newly built version is what is being launched? You can also search for where the config is being parsed in the module and add additional logs there

I had tried adding some std::cout messages, but did not see any of them come across (did see a build error when i originally introduced a syntax error, but resolved that) - not sure if I messed something up or if things just crashed before the messages were hit. I'm out of time again, so I'll have to try again on Monday.

shankari commented 1 month ago

Attempting to test the compiled version with SIL before copying out the cross-compiled version, I created a new docker-compose that launches the cross-compile container. We need to do this through docker-compose, since otherwise, the MQTT server will not be running for the manager to connect to.

After using the attached docker compose file, trying to start the manager fails in the energy manager module ``` /ext/source # sh build/run-scripts/run-sil.sh 2024-10-08 15:22:20.126075 [INFO] manager :: ________ __ _ 2024-10-08 15:22:20.126206 [INFO] manager :: | ____\ \ / / | | 2024-10-08 15:22:20.126264 [INFO] manager :: | |__ \ \ / /__ _ __ ___ ___| |_ 2024-10-08 15:22:20.126322 [INFO] manager :: | __| \ \/ / _ \ '__/ _ \/ __| __| 2024-10-08 15:22:20.126394 [INFO] manager :: | |____ \ / __/ | | __/\__ \ |_ 2024-10-08 15:22:20.126420 [INFO] manager :: |______| \/ \___|_| \___||___/\__| 2024-10-08 15:22:20.126498 [INFO] manager :: 2024-10-08 15:22:20.126524 [INFO] manager :: Using MQTT broker mqtt-server:1883 2024-10-08 15:22:20.126556 [INFO] manager :: Telemetry enabled libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 2024-10-08 15:22:20.168576 [INFO] everest_ctrl :: Launching controller service on port 8849 2024-10-08 15:22:20.209233 [INFO] manager :: Loading config file at: /ext/source/config/config-sil.yaml 2024-10-08 15:22:20.629058 [INFO] manager :: Config loading completed in 464ms libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda2024-10-08 15:22:21.600856 [INFO] energy_manager: :: Module energy_manager initialized [690ms]:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 2024-10-08 15:22:21.619681 [INFO] connector_1:Evs :: Module connector_1 initialized [808ms] 2024-10-08 15:22:21.656204 [INFO] auth:Auth :: Module auth initialized [899ms] libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 2024-10-08 15:22:21.736487 [INFO] api:API :: Module api initialized [1028ms]libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda :Merge mismatch for function 4166 2024-10-08 15:22:21.797035 [INFO] evse_security:E :: Module evse_security initialized [776ms] libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 2024-10-08 15:22:21.980378 [INFO] grid_connection :: Module grid_connection_point initialized [899ms] 2024-10-08 15:22:22.247812 [INFO] iso15118_charge :: TCP server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:61341 2024-10-08 15:22:22.247925 [INFO] iso15118_charge :: TLS server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:64109 2024-10-08 15:22:22.248010 [INFO] iso15118_charge :: SDP socket setup succeeded 2024-10-08 15:22:22.248224 [INFO] iso15118_charge :: Module iso15118_charger initialized [905ms] 2024-10-08 15:22:22.285081 [INFO] persistent_stor :: Module persistent_store initialized [862ms] 2024-10-08 15:22:22.336054 [INFO] setup:Setup :: Module setup initialized [742ms] 2024-10-08 15:22:22.561877 [INFO] token_provider: :: Module token_provider initialized [679ms] 2024-10-08 15:22:22.574378 [INFO] token_validator :: Module token_validator initialized [614ms] 2024-10-08 15:22:22.773319 [INFO] manager :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [2658ms] πŸš™πŸš™πŸš™ 2024-10-08 15:22:22.782180 [INFO] energy_manager: :: returning optimized values vector of length 0 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 2024-10-08 15:22:23.277953 [INFO] connector_1:Evs :: Max AC hardware capabilities: 32A/3ph 2024-10-08 15:22:23.285201 [INFO] connector_1:Evs :: Ignoring BSP Event, BSP is not enabled yet. 2024-10-08 15:22:23.300627 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Module energy_manager (pid: 409) exited with status: 11. Terminating all modules. 2024-10-08 15:22:23.301908 [INFO] manager :: SIGTERM of child: api (pid: 405) succeeded. 2024-10-08 15:22:23.302207 [INFO] manager :: SIGTERM of child: auth (pid: 406) succeeded. 2024-10-08 15:22:23.302796 [INFO] manager :: SIGTERM of child: connector_1 (pid: 407) succeeded. 2024-10-08 15:22:23.302921 [INFO] manager :: SIGTERM of child: connector_1_powerpath (pid: 408) succeeded. 2024-10-08 15:22:23.303061 [INFO] manager :: SIGTERM of child: ev_manager (pid: 416) succeeded. 2024-10-08 15:22:23.303259 [INFO] manager :: SIGTERM of child: evse_security (pid: 417) succeeded. 2024-10-08 15:22:23.303356 [INFO] manager :: SIGTERM of child: grid_connection_point (pid: 424) succeeded. 2024-10-08 15:22:23.303571 [INFO] manager :: SIGTERM of child: iso15118_car (pid: 425) succeeded. 2024-10-08 15:22:23.303707 [INFO] manager :: SIGTERM of child: iso15118_charger (pid: 426) succeeded. 2024-10-08 15:22:23.303820 [INFO] manager :: SIGTERM of child: persistent_store (pid: 427) succeeded. 2024-10-08 15:22:23.303912 [INFO] manager :: SIGTERM of child: setup (pid: 428) succeeded. 2024-10-08 15:22:23.304009 [INFO] manager :: SIGTERM of child: slac (pid: 454) succeeded. 2024-10-08 15:22:23.304162 [INFO] manager :: SIGTERM of child: token_provider (pid: 534) succeeded. 2024-10-08 15:22:23.304208 [INFO] manager :: SIGTERM of child: token_validator (pid: 571) succeeded. 2024-10-08 15:22:23.304231 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Exiting manager. libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 /ext/source # ```

we get the gcda warnings even when running successfully, so they are not an issue, but removing them anyway (find . -name \*.gcda | xargs rm) to avoid freaking out about them.

Still fails ``` /ext/source # sh build/run-scripts/run-sil.sh 2024-10-08 15:45:37.209231 [INFO] manager :: ________ __ _ 2024-10-08 15:45:37.209378 [INFO] manager :: | ____\ \ / / | | 2024-10-08 15:45:37.209453 [INFO] manager :: | |__ \ \ / /__ _ __ ___ ___| |_ 2024-10-08 15:45:37.209576 [INFO] manager :: | __| \ \/ / _ \ '__/ _ \/ __| __| 2024-10-08 15:45:37.209646 [INFO] manager :: | |____ \ / __/ | | __/\__ \ |_ 2024-10-08 15:45:37.209679 [INFO] manager :: |______| \/ \___|_| \___||___/\__| 2024-10-08 15:45:37.209699 [INFO] manager :: 2024-10-08 15:45:37.209715 [INFO] manager :: Using MQTT broker mqtt-server:1883 2024-10-08 15:45:37.209743 [INFO] manager :: Telemetry enabled 2024-10-08 15:45:37.236519 [INFO] everest_ctrl :: Launching controller service on port 8849 2024-10-08 15:45:37.278410 [INFO] manager :: Loading config file at: /ext/source/config/config-sil.yaml 2024-10-08 15:45:37.701311 [INFO] manager :: Config loading completed in 469ms 2024-10-08 15:45:38.420649 [INFO] auth:Auth :: Module auth initialized [606ms] 2024-10-08 15:45:38.521328 [INFO] api:API :: Module api initialized [745ms] 2024-10-08 15:45:38.618133 [INFO] connector_1:Evs :: Module connector_1 initialized [760ms] 2024-10-08 15:45:38.686380 [INFO] evse_security:E :: Module evse_security initialized [650ms] 2024-10-08 15:45:38.740136 [INFO] grid_connection :: Module grid_connection_point initialized [659ms] 2024-10-08 15:45:38.822801 [INFO] energy_manager: :: Module energy_manager initialized [878ms] 2024-10-08 15:45:39.177919 [INFO] setup:Setup :: Module setup initialized [712ms] 2024-10-08 15:45:39.184127 [INFO] token_provider: :: Module token_provider initialized [576ms] 2024-10-08 15:45:39.192183 [INFO] iso15118_charge :: TCP server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:61341 2024-10-08 15:45:39.192338 [INFO] iso15118_charge :: TLS server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:64109 2024-10-08 15:45:39.192394 [INFO] iso15118_charge :: SDP socket setup succeeded 2024-10-08 15:45:39.193115 [INFO] iso15118_charge :: Module iso15118_charger initialized [909ms] 2024-10-08 15:45:39.220405 [INFO] token_validator :: Module token_validator initialized [561ms] 2024-10-08 15:45:39.298467 [INFO] persistent_stor :: Module persistent_store initialized [938ms] 2024-10-08 15:45:39.722150 [INFO] manager :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [2523ms] πŸš™πŸš™πŸš™ 2024-10-08 15:45:39.732989 [INFO] energy_manager: :: returning optimized values vector of length 0 2024-10-08 15:45:39.995171 [INFO] connector_1:Evs :: Ignoring BSP Event, BSP is not enabled yet. 2024-10-08 15:45:40.095450 [INFO] connector_1:Evs :: Max AC hardware capabilities: 32A/3ph 2024-10-08 15:45:40.150854 [INFO] connector_1:Evs :: AC HLC mode enabled. 2024-10-08 15:45:40.153659 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Module energy_manager (pid: 694) exited with status: 11. Terminating all modules. 2024-10-08 15:45:40.155050 [INFO] manager :: SIGTERM of child: api (pid: 690) succeeded. 2024-10-08 15:45:40.155286 [INFO] manager :: SIGTERM of child: auth (pid: 691) succeeded. 2024-10-08 15:45:40.156693 [INFO] manager :: SIGTERM of child: connector_1 (pid: 692) succeeded. 2024-10-08 15:45:40.156787 [INFO] manager :: SIGTERM of child: connector_1_powerpath (pid: 693) succeeded. 2024-10-08 15:45:40.156871 [INFO] manager :: SIGTERM of child: ev_manager (pid: 701) succeeded. 2024-10-08 15:45:40.156947 [INFO] manager :: SIGTERM of child: evse_security (pid: 702) succeeded. 2024-10-08 15:45:40.157041 [INFO] manager :: SIGTERM of child: grid_connection_point (pid: 709) succeeded. 2024-10-08 15:45:40.157139 [INFO] manager :: SIGTERM of child: iso15118_car (pid: 710) succeeded. 2024-10-08 15:45:40.158107 [INFO] manager :: SIGTERM of child: iso15118_charger (pid: 711) succeeded. 2024-10-08 15:45:40.158240 [INFO] manager :: SIGTERM of child: persistent_store (pid: 712) succeeded. 2024-10-08 15:45:40.158345 [INFO] manager :: SIGTERM of child: setup (pid: 713) succeeded. 2024-10-08 15:45:40.158415 [INFO] manager :: SIGTERM of child: slac (pid: 715) succeeded. 2024-10-08 15:45:40.158558 [INFO] manager :: SIGTERM of child: token_provider (pid: 764) succeeded. 2024-10-08 15:45:40.158643 [INFO] manager :: SIGTERM of child: token_validator (pid: 823) succeeded. 2024-10-08 15:45:40.158693 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Exiting manager. ```

Is this because we are trying to run the cross-compiled version? No. There is no cross-compiled version yet.

/ext/source # find . -name \*manager
./build/_deps/everest-framework-build/src/manager
./build/generated/include/generated/interfaces/evse_manager
./build/generated/include/generated/interfaces/energy_manager
./build/dist/bin/manager
./build-cross/_deps/everest-framework-build/src/manager
./build-cross/generated/include/generated/interfaces/evse_manager
./build-cross/generated/include/generated/interfaces/energy_manager

Let's delete build-cross and build and try to rebuild

Failing to download due to HTTP/2 on NREL laptops, configuring `git` to use HTTP1 ``` -- Performing Test LWS_HAVE_SSL_EXTRA_CHAIN_CERTS -- Performing Test LWS_HAVE_SSL_EXTRA_CHAIN_CERTS - Success -- Performing Test LWS_HAVE_EVP_MD_CTX_free -- Performing Test LWS_HAVE_EVP_MD_CTX_free - Success -- Performing Test LWS_HAVE_OPENSSL_STACK -- Performing Test LWS_HAVE_OPENSSL_STACK - Success -- Looking for ECDSA_SIG_set0 -- Looking for ECDSA_SIG_set0 - found -- Looking for BN_bn2binpad -- Looking for BN_bn2binpad - found -- Looking for EVP_aes_128_wrap -- Looking for EVP_aes_128_wrap - found -- Looking for EC_POINT_get_affine_coordinates -- Looking for EC_POINT_get_affine_coordinates - found -- Looking for TLS_client_method -- Looking for TLS_client_method - found -- Looking for TLSv1_2_client_method -- Looking for TLSv1_2_client_method - found Searching for OpenSSL executable and dlls OpenSSL executable: /usr/bin/openssl GENCERTS = 0 DIR /ext/source/build/_deps/libwebsockets-build CMP /ext/source/build/_deps/libwebsockets-src/cmake -- CPM: everest-framework: adding package nlohmann_json@3.11.2 (v3.11.2) [ 11%] Creating directories for 'nlohmann_json-populate' [ 22%] Performing download step (git clone) for 'nlohmann_json-populate' Cloning into 'nlohmann_json-src'... error: RPC failed; curl 92 HTTP/2 stream 5 was not closed cleanly: CANCEL (err 8) error: 6555 bytes of body are still expected fetch-pack: unexpected disconnect while reading sideband packet fatal: early EOF fatal: fetch-pack: invalid index-pack output Cloning into 'nlohmann_json-src'... error: RPC failed; curl 92 HTTP/2 stream 5 was not closed cleanly: CANCEL (err 8) error: 4213 bytes of body are still expected fetch-pack: unexpected disconnect while reading sideband packet fatal: early EOF fatal: fetch-pack: invalid index-pack output Cloning into 'nlohmann_json-src'... error: RPC failed; curl 92 HTTP/2 stream 5 was not closed cleanly: CANCEL (err 8) error: 7588 bytes of body are still expected fetch-pack: unexpected disconnect while reading sideband packet fatal: early EOF fatal: fetch-pack: invalid index-pack output -- Had to git clone more than once: 3 times. CMake Error at nlohmann_json-subbuild/nlohmann_json-populate-prefix/tmp/nlohmann_json-populate-gitclone.cmake:39 (message): Failed to clone repository: 'https://github.com/nlohmann/json' make[2]: *** [CMakeFiles/nlohmann_json-populate.dir/build.make:102: nlohmann_json-populate-prefix/src/nlohmann_json-populate-stamp/nlohmann_json-populate-download] Error 1 make[1]: *** [CMakeFiles/Makefile2:83: CMakeFiles/nlohmann_json-populate.dir/all] Error 2 make: *** [Makefile:91: all] Error 2 CMake Error at /usr/share/cmake/Modules/FetchContent.cmake:1604 (message): Build step for nlohmann_json failed: 2 Call Stack (most recent call first): /usr/share/cmake/Modules/FetchContent.cmake:1744:EVAL:2 (__FetchContent_directPopulate) /usr/share/cmake/Modules/FetchContent.cmake:1744 (cmake_language) /usr/lib/cmake/everest-cmake/3rd_party/CPM.cmake:885 (FetchContent_Populate) /usr/lib/cmake/everest-cmake/3rd_party/CPM.cmake:685 (cpm_fetch_package) build/_deps/everest-framework-build/dependencies.cmake:30 (CPMAddPackage) /usr/lib/cmake/everest-cmake/edm.cmake:23 (include) build/_deps/everest-framework-src/CMakeLists.txt:51 (evc_setup_edm) -- Configuring incomplete, errors occurred! See also "/ext/source/build/CMakeFiles/CMakeOutput.log". See also "/ext/source/build/CMakeFiles/CMakeError.log". ``` Potential fix? from https://stackoverflow.com/questions/59282476/error-rpc-failed-curl-92-http-2-stream-0-was-not-closed-cleanly-protocol-erro#59474908 ``` /ext/source/build # git config --global http.version HTTP/1.1 ```
Fails consistently on another clone; need to make it a shallow clone; setting the `CPM_SOURCE_CACHE` works ``` [ 11%] Performing download step (git clone) for 'nlohmann_json-populate' Cloning into 'nlohmann_json-src'... error: RPC failed; curl 18 transfer closed with outstanding read data remaining error: 6032 bytes of body are still expected fetch-pack: unexpected disconnect while reading sideband packet fatal: early EOF fatal: fetch-pack: invalid index-pack output Cloning into 'nlohmann_json-src'... error: RPC failed; curl 18 transfer closed with outstanding read data remaining error: 126 bytes of body are still expected fetch-pack: unexpected disconnect while reading sideband packet fatal: early EOF fatal: fetch-pack: invalid index-pack output Cloning into 'nlohmann_json-src'... error: RPC failed; curl 18 transfer closed with outstanding read data remaining error: 3548 bytes of body are still expected fetch-pack: unexpected disconnect while reading sideband packet fatal: early EOF fatal: fetch-pack: invalid index-pack output -- Had to git clone more than once: 3 times. CMake Error at nlohmann_json-subbuild/nlohmann_json-populate-prefix/tmp/nlohmann_json-populate-gitclone.cmake:39 (message): Failed to clone repository: 'https://github.com/nlohmann/json' make[2]: *** [CMakeFiles/nlohmann_json-populate.dir/build.make:102: nlohmann_json-populate-prefix/src/nlohmann_json-populate-stamp/nlohmann_json-populate-download] Error 1 make[1]: *** [CMakeFiles/Makefile2:83: CMakeFiles/nlohmann_json-populate.dir/all] Error 2 make: *** [Makefile:91: all] Error 2 CMake Error at /usr/share/cmake/Modules/FetchContent.cmake:1604 (message): Build step for nlohmann_json failed: 2 Call Stack (most recent call first): /usr/share/cmake/Modules/FetchContent.cmake:1744:EVAL:2 (__FetchContent_directPopulate) /usr/share/cmake/Modules/FetchContent.cmake:1744 (cmake_language) /usr/lib/cmake/everest-cmake/3rd_party/CPM.cmake:885 (FetchContent_Populate) /usr/lib/cmake/everest-cmake/3rd_party/CPM.cmake:685 (cpm_fetch_package) build/_deps/everest-framework-build/dependencies.cmake:30 (CPMAddPackage) /usr/lib/cmake/everest-cmake/edm.cmake:23 (include) build/_deps/everest-framework-src/CMakeLists.txt:51 (evc_setup_edm) -- Configuring incomplete, errors occurred! See also "/ext/source/build/CMakeFiles/CMakeOutput.log". See also "/ext/source/build/CMakeFiles/CMakeError.log". ``` Manual clone also fails ``` /ext/source/build # git clone https://github.com/nlohmann/json Cloning into 'json'... remote: Enumerating objects: 38228, done. remote: Counting objects: 100% (110/110), done. remote: Compressing objects: 100% (68/68), done. error: RPC failed; curl 18 transfer closed with outstanding read data remaining error: 478 bytes of body are still expected fetch-pack: unexpected disconnect while reading sideband packet fatal: early EOF fatal: fetch-pack: invalid index-pack output ``` Using a shallow clone works ``` /ext/source/build # git clone https://github.com/nlohmann/json --depth 1 Cloning into 'json'... remote: Enumerating objects: 1129, done. remote: Counting objects: 100% (1129/1129), done. remote: Compressing objects: 100% (810/810), done. remote: Total 1129 (delta 257), reused 903 (delta 244), pack-reused 0 (from 0) Receiving objects: 100% (1129/1129), 7.71 MiB | 375.00 KiB/s, done. Resolving deltas: 100% (257/257), done. ``` To make cpm use a shallow clone, we need to use the CPM_SOURCE_CACHE > Automatic shallow clone: if a version tag (e.g. v2.2.0) is provided and CPM_SOURCE_CACHE is used, CPM.cmake will perform a shallow clone of the dependency, which should be significantly faster while using less storage than a full clone. ``` # export CPM_SOURCE_CACHE=/ext/cache/cpm # cmake -DBUILD_TESTING=ON .. -- Could NOT find Doxygen (missing: DOXYGEN_EXECUTABLE) -- APPENDING /ext/source/tests/everest-core_tests to EVEREST_PROJECT_DIRS -- Adding error definitions from /ext/source/tests/everest-core_tests/errors -- Adding interface definitions from /ext/source/tests/everest-core_tests/interfaces -- Setting up C++ module TestErrorHandling -- everest-core_tests modules that will be built: API;Auth;EnergyManager;EnergyNode;ErrorHistory;EvseManager;EvseSecurity;EvseSlac;EvseV2G;EvSlac;GenericPowermeter;JsTibber;LemDCBM400600;OCPP;OCPP201;PacketSniffer;PersistentStore;PN532TokenProvider;PyEvJosev;Setup;SerialCommHub;Store;System;YetiDriver;YetiEvDriver;PowermeterBSM;DummyV2G;MicroMegaWattBSP;DPM1000;OCPPExtensionExample;DummyTokenValidator;DummyTokenProvider;DummyTokenProviderManual;PhyVersoBSP;Example;ExampleUser;ExampleErrorRaiser;ExampleErrorSubscriber;PyExampleErrorRaiser;PyExampleErrorSubscriber;JsExampleErrorRaiser;JsExampleErrorSubscriber;DCSupplySimulator;IMDSimulator;JsEvManager;JsDCSupplySimulator;JsSlacSimulator;JsYetiSimulator;TestErrorHandling -- Configuring done -- Generating done -- Build files have been written to: /ext/source/build ```
Full rebuild + restart still fails in the same way, even for the simple, non-OCPP config ``` /ext/source # sh build/run-scripts/run-sil.sh 2024-10-08 17:58:19.985574 [INFO] manager :: ________ __ _ 2024-10-08 17:58:19.985813 [INFO] manager :: | ____\ \ / / | | 2024-10-08 17:58:19.985885 [INFO] manager :: | |__ \ \ / /__ _ __ ___ ___| |_ 2024-10-08 17:58:19.985957 [INFO] manager :: | __| \ \/ / _ \ '__/ _ \/ __| __| 2024-10-08 17:58:19.986026 [INFO] manager :: | |____ \ / __/ | | __/\__ \ |_ 2024-10-08 17:58:19.986066 [INFO] manager :: |______| \/ \___|_| \___||___/\__| 2024-10-08 17:58:19.986129 [INFO] manager :: 2024-10-08 17:58:19.986235 [INFO] manager :: Using MQTT broker mqtt-server:1883 2024-10-08 17:58:19.986325 [INFO] manager :: Telemetry enabled 2024-10-08 17:58:20.028665 [INFO] everest_ctrl :: Launching controller service on port 8849 2024-10-08 17:58:20.069331 [INFO] manager :: Loading config file at: /ext/source/config/config-sil.yaml 2024-10-08 17:58:20.493064 [INFO] manager :: Config loading completed in 469ms 2024-10-08 17:58:21.184372 [INFO] auth:Auth :: Module auth initialized [578ms] 2024-10-08 17:58:21.198751 [INFO] api:API :: Module api initialized [632ms] 2024-10-08 17:58:21.458008 [INFO] grid_connection :: Module grid_connection_point initialized [585ms] 2024-10-08 17:58:21.677674 [INFO] evse_security:E :: Module evse_security initialized [846ms] 2024-10-08 17:58:21.690158 [INFO] connector_1:Evs :: Module connector_1 initialized [1036ms] 2024-10-08 17:58:21.770862 [INFO] energy_manager: :: Module energy_manager initialized [1030ms] 2024-10-08 17:58:21.830271 [INFO] persistent_stor :: Module persistent_store initialized [641ms] 2024-10-08 17:58:21.836751 [INFO] setup:Setup :: Module setup initialized [596ms] 2024-10-08 17:58:22.056107 [INFO] iso15118_charge :: TCP server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:61341 2024-10-08 17:58:22.056425 [INFO] iso15118_charge :: TLS server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:64109 2024-10-08 17:58:22.056493 [INFO] iso15118_charge :: SDP socket setup succeeded 2024-10-08 17:58:22.057442 [INFO] iso15118_charge :: Module iso15118_charger initialized [938ms] 2024-10-08 17:58:22.058963 [INFO] token_validator :: Module token_validator initialized [561ms] 2024-10-08 17:58:22.144637 [INFO] token_provider: :: Module token_provider initialized [690ms] 2024-10-08 17:58:22.502425 [INFO] manager :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [2528ms] πŸš™πŸš™πŸš™ 2024-10-08 17:58:22.516897 [INFO] energy_manager: :: returning optimized values vector of length 0 2024-10-08 17:58:22.777740 [INFO] connector_1:Evs :: Ignoring BSP Event, BSP is not enabled yet. 2024-10-08 17:58:22.841463 [INFO] connector_1:Evs :: Max AC hardware capabilities: 32A/3ph 2024-10-08 17:58:22.897736 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Module energy_manager (pid: 13453) exited with status: 11. Terminating all modules. 2024-10-08 17:58:22.899042 [INFO] manager :: SIGTERM of child: api (pid: 13449) succeeded. 2024-10-08 17:58:22.899194 [INFO] manager :: SIGTERM of child: auth (pid: 13450) succeeded. 2024-10-08 17:58:22.900170 [INFO] manager :: SIGTERM of child: connector_1 (pid: 13451) succeeded. 2024-10-08 17:58:22.900298 [INFO] manager :: SIGTERM of child: connector_1_powerpath (pid: 13452) succeeded. 2024-10-08 17:58:22.900372 [INFO] manager :: SIGTERM of child: ev_manager (pid: 13460) succeeded. 2024-10-08 17:58:22.900530 [INFO] manager :: SIGTERM of child: evse_security (pid: 13461) succeeded. 2024-10-08 17:58:22.900731 [INFO] manager :: SIGTERM of child: grid_connection_point (pid: 13468) succeeded. 2024-10-08 17:58:22.900823 [INFO] manager :: SIGTERM of child: iso15118_car (pid: 13469) succeeded. 2024-10-08 17:58:22.900925 [INFO] manager :: SIGTERM of child: iso15118_charger (pid: 13470) succeeded. 2024-10-08 17:58:22.901174 [INFO] manager :: SIGTERM of child: persistent_store (pid: 13471) succeeded. 2024-10-08 17:58:22.901282 [INFO] manager :: SIGTERM of child: setup (pid: 13473) succeeded. 2024-10-08 17:58:22.901374 [INFO] manager :: SIGTERM of child: slac (pid: 13505) succeeded. 2024-10-08 17:58:22.901501 [INFO] manager :: SIGTERM of child: token_provider (pid: 13506) succeeded. 2024-10-08 17:58:22.901586 [INFO] manager :: SIGTERM of child: token_validator (pid: 13513) succeeded. 2024-10-08 17:58:22.901689 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Exiting manager. ```
shankari commented 1 month ago

Edited build/dist/etc/everest/default_logging.cfg and set the filter to Filter="%Severity% >= INFO or (%Process% contains energy_manager and %Severity% >= DEBG) "

Doesn't really give us a smoking gun ``` /ext/source # sh build/run-scripts/run-sil.sh 2024-10-08 19:17:06.722889 [INFO] manager :: ________ __ _ 2024-10-08 19:17:06.723019 [INFO] manager :: | ____\ \ / / | | 2024-10-08 19:17:06.723051 [INFO] manager :: | |__ \ \ / /__ _ __ ___ ___| |_ 2024-10-08 19:17:06.723105 [INFO] manager :: | __| \ \/ / _ \ '__/ _ \/ __| __| 2024-10-08 19:17:06.723137 [INFO] manager :: | |____ \ / __/ | | __/\__ \ |_ 2024-10-08 19:17:06.723187 [INFO] manager :: |______| \/ \___|_| \___||___/\__| 2024-10-08 19:17:06.723325 [INFO] manager :: 2024-10-08 19:17:06.723355 [INFO] manager :: Using MQTT broker mqtt-server:1883 2024-10-08 19:17:06.723386 [INFO] manager :: Telemetry enabled 2024-10-08 19:17:06.767627 [INFO] everest_ctrl :: Launching controller service on port 8849 2024-10-08 19:17:06.806284 [INFO] manager :: Loading config file at: /ext/source/config/config-sil.yaml 2024-10-08 19:17:07.196247 [INFO] manager :: Config loading completed in 433ms 2024-10-08 19:17:07.471076 [DEBG] energy_manager void Everest::Logging::init(const std::string&, std::string) :: Logger initialized (using /ext/source/build/dist/etc/everest/default_logging.cfg)... 2024-10-08 19:17:07.471282 [DEBG] energy_manager static Everest::schemas Everest::Config::load_schemas(const std::filesystem::__cxx11::path&) :: Loading base schema files for config and manifests... from: /ext/source/build/dist/share/everest/schemas 2024-10-08 19:17:07.471429 [DEBG] energy_manager static Everest::json Everest::Config::load_schema(const std::filesystem::__cxx11::path&) :: Loading schema file at: /ext/source/build/dist/share/everest/schemas/config.yaml 2024-10-08 19:17:07.495049 [DEBG] energy_manager static Everest::json Everest::Config::load_schema(const std::filesystem::__cxx11::path&) :: Loading schema file at: /ext/source/build/dist/share/everest/schemas/manifest.yaml 2024-10-08 19:17:07.501443 [DEBG] energy_manager static Everest::json Everest::Config::load_schema(const std::filesystem::__cxx11::path&) :: Loading schema file at: /ext/source/build/dist/share/everest/schemas/interface.yaml 2024-10-08 19:17:07.508222 [DEBG] energy_manager static Everest::json Everest::Config::load_schema(const std::filesystem::__cxx11::path&) :: Loading schema file at: /ext/source/build/dist/share/everest/schemas/type.yaml 2024-10-08 19:17:07.514702 [DEBG] energy_manager static Everest::json Everest::Config::load_schema(const std::filesystem::__cxx11::path&) :: Loading schema file at: /ext/source/build/dist/share/everest/schemas/error-declaration-list.yaml 2024-10-08 19:17:07.540255 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module api:API, loading and verifying manifest... 2024-10-08 19:17:07.540929 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/API/manifest.yaml 2024-10-08 19:17:07.554398 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: main 2024-10-08 19:17:07.554982 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/empty.yaml 2024-10-08 19:17:07.568290 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module auth:Auth, loading and verifying manifest... 2024-10-08 19:17:07.568714 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/Auth/manifest.yaml 2024-10-08 19:17:07.577244 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: main 2024-10-08 19:17:07.577704 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/auth.yaml 2024-10-08 19:17:07.590515 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: reservation 2024-10-08 19:17:07.590946 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/reservation.yaml 2024-10-08 19:17:07.603680 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module connector_1:EvseManager, loading and verifying manifest... 2024-10-08 19:17:07.604231 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/EvseManager/manifest.yaml 2024-10-08 19:17:07.619258 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: energy_grid 2024-10-08 19:17:07.619567 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/energy.yaml 2024-10-08 19:17:07.632033 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: evse 2024-10-08 19:17:07.632350 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/evse_manager.yaml 2024-10-08 19:17:07.666523 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: random_delay 2024-10-08 19:17:07.666744 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/uk_random_delay.yaml 2024-10-08 19:17:07.679650 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: token_provider 2024-10-08 19:17:07.679915 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/auth_token_provider.yaml 2024-10-08 19:17:07.694053 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module connector_1_powerpath:JsYetiSimulator, loading and verifying manifest... 2024-10-08 19:17:07.694390 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/JsYetiSimulator/manifest.yaml 2024-10-08 19:17:07.700166 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: board_support 2024-10-08 19:17:07.700451 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/evse_board_support.yaml 2024-10-08 19:17:07.725607 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: connector_lock 2024-10-08 19:17:07.725949 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/connector_lock.yaml 2024-10-08 19:17:07.739383 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: ev_board_support 2024-10-08 19:17:07.739593 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/ev_board_support.yaml 2024-10-08 19:17:07.759593 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: powermeter 2024-10-08 19:17:07.759807 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/powermeter.yaml 2024-10-08 19:17:07.771205 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: rcd 2024-10-08 19:17:07.771395 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/ac_rcd.yaml 2024-10-08 19:17:07.784067 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module energy_manager:EnergyManager, loading and verifying manifest... 2024-10-08 19:17:07.784345 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/EnergyManager/manifest.yaml 2024-10-08 19:17:07.791694 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: main 2024-10-08 19:17:07.791929 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/energy_manager.yaml 2024-10-08 19:17:07.803189 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module ev_manager:JsEvManager, loading and verifying manifest... 2024-10-08 19:17:07.803468 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/JsEvManager/manifest.yaml 2024-10-08 19:17:07.814182 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: main 2024-10-08 19:17:07.814524 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/car_simulator.yaml 2024-10-08 19:17:07.831414 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module evse_security:EvseSecurity, loading and verifying manifest... 2024-10-08 19:17:07.831670 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/EvseSecurity/manifest.yaml 2024-10-08 19:17:07.839840 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: main 2024-10-08 19:17:07.840029 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/evse_security.yaml 2024-10-08 19:17:07.878282 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module grid_connection_point:EnergyNode, loading and verifying manifest... 2024-10-08 19:17:07.878495 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/EnergyNode/manifest.yaml 2024-10-08 19:17:07.885836 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: energy_grid 2024-10-08 19:17:07.886284 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/energy.yaml 2024-10-08 19:17:07.898363 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: external_limits 2024-10-08 19:17:07.898586 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/external_energy_limits.yaml 2024-10-08 19:17:07.908701 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module iso15118_car:PyEvJosev, loading and verifying manifest... 2024-10-08 19:17:07.908973 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/PyEvJosev/manifest.yaml 2024-10-08 19:17:07.916318 [INFO] api:API :: Module api initialized [641ms] 2024-10-08 19:17:07.917519 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: ev 2024-10-08 19:17:07.917639 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/ISO15118_ev.yaml 2024-10-08 19:17:07.935060 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module iso15118_charger:EvseV2G, loading and verifying manifest... 2024-10-08 19:17:07.935219 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/EvseV2G/manifest.yaml 2024-10-08 19:17:07.940049 [INFO] auth:Auth :: Module auth initialized [618ms] 2024-10-08 19:17:07.943537 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: charger 2024-10-08 19:17:07.943653 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/ISO15118_charger.yaml 2024-10-08 19:17:07.999441 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module persistent_store:PersistentStore, loading and verifying manifest... 2024-10-08 19:17:07.999559 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/PersistentStore/manifest.yaml 2024-10-08 19:17:08.005055 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: main 2024-10-08 19:17:08.005188 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/kvs.yaml 2024-10-08 19:17:08.019976 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module setup:Setup, loading and verifying manifest... 2024-10-08 19:17:08.020090 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/Setup/manifest.yaml 2024-10-08 19:17:08.028150 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: main 2024-10-08 19:17:08.028298 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/empty.yaml 2024-10-08 19:17:08.037311 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module slac:JsSlacSimulator, loading and verifying manifest... 2024-10-08 19:17:08.037434 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/JsSlacSimulator/manifest.yaml 2024-10-08 19:17:08.044193 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: ev 2024-10-08 19:17:08.044321 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/ev_slac.yaml 2024-10-08 19:17:08.057941 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: evse 2024-10-08 19:17:08.058054 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/slac.yaml 2024-10-08 19:17:08.077152 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module token_provider:DummyTokenProvider, loading and verifying manifest... 2024-10-08 19:17:08.077413 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/DummyTokenProvider/manifest.yaml 2024-10-08 19:17:08.084502 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: main 2024-10-08 19:17:08.084600 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/auth_token_provider.yaml 2024-10-08 19:17:08.095950 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Found module token_validator:DummyTokenValidator, loading and verifying manifest... 2024-10-08 19:17:08.096119 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading module manifest file at: /ext/source/build/dist/libexec/everest/modules/DummyTokenValidator/manifest.yaml 2024-10-08 19:17:08.102455 [DEBG] energy_manager void Everest::Config::load_and_validate_manifest(const std::string&, const Everest::json&) :: Loading interface for implementation: main 2024-10-08 19:17:08.102573 [DEBG] energy_manager Everest::json Everest::Config::load_interface_file(const std::string&) :: Loading interface file at: /ext/source/build/dist/share/everest/interfaces/auth_token_validator.yaml 2024-10-08 19:17:08.113930 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Resolving module reguirements... 2024-10-08 19:17:08.114069 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of api:API lists requirement 'evse_manager' which will be fulfilled by connector_1:EvseManager->evse:evse_manager... 2024-10-08 19:17:08.114319 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of api:API lists OPTIONAL requirement 'ocpp' which could not be fulfilled and will be ignored... 2024-10-08 19:17:08.114379 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of api:API lists OPTIONAL requirement 'random_delay' which could not be fulfilled and will be ignored... 2024-10-08 19:17:08.114517 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of auth:Auth lists requirement 'evse_manager' which will be fulfilled by connector_1:EvseManager->evse:evse_manager... 2024-10-08 19:17:08.114698 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of auth:Auth lists requirement 'token_provider' which will be fulfilled by token_provider:DummyTokenProvider->main:auth_token_provider... 2024-10-08 19:17:08.114841 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of auth:Auth lists requirement 'token_validator' which will be fulfilled by token_validator:DummyTokenValidator->main:auth_token_validator... 2024-10-08 19:17:08.115311 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of connector_1:EvseManager lists requirement 'ac_rcd' which will be fulfilled by connector_1_powerpath:JsYetiSimulator->rcd:ac_rcd... 2024-10-08 19:17:08.115509 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of connector_1:EvseManager lists requirement 'bsp' which will be fulfilled by connector_1_powerpath:JsYetiSimulator->board_support:evse_board_support... 2024-10-08 19:17:08.115727 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of connector_1:EvseManager lists requirement 'connector_lock' which will be fulfilled by connector_1_powerpath:JsYetiSimulator->connector_lock:connector_lock... 2024-10-08 19:17:08.115903 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of connector_1:EvseManager lists requirement 'hlc' which will be fulfilled by iso15118_charger:EvseV2G->charger:ISO15118_charger... 2024-10-08 19:17:08.116049 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of connector_1:EvseManager lists OPTIONAL requirement 'imd' which could not be fulfilled and will be ignored... 2024-10-08 19:17:08.116111 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of connector_1:EvseManager lists OPTIONAL requirement 'powermeter_car_side' which could not be fulfilled and will be ignored... 2024-10-08 19:17:08.116376 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of connector_1:EvseManager lists requirement 'powermeter_grid_side' which will be fulfilled by connector_1_powerpath:JsYetiSimulator->powermeter:powermeter... 2024-10-08 19:17:08.116573 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of connector_1:EvseManager lists OPTIONAL requirement 'powersupply_DC' which could not be fulfilled and will be ignored... 2024-10-08 19:17:08.116646 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of connector_1:EvseManager lists requirement 'slac' which will be fulfilled by slac:JsSlacSimulator->evse:slac... 2024-10-08 19:17:08.116787 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of energy_manager:EnergyManager lists requirement 'energy_trunk' which will be fulfilled by grid_connection_point:EnergyNode->energy_grid:energy... 2024-10-08 19:17:08.116986 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of ev_manager:JsEvManager lists requirement 'ev' which will be fulfilled by iso15118_car:PyEvJosev->ev:ISO15118_ev... 2024-10-08 19:17:08.117116 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of ev_manager:JsEvManager lists requirement 'ev_board_support' which will be fulfilled by connector_1_powerpath:JsYetiSimulator->ev_board_support:ev_board_support... 2024-10-08 19:17:08.117204 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of ev_manager:JsEvManager lists OPTIONAL requirement 'powermeter' which could not be fulfilled and will be ignored... 2024-10-08 19:17:08.117269 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of ev_manager:JsEvManager lists requirement 'slac' which will be fulfilled by slac:JsSlacSimulator->ev:ev_slac... 2024-10-08 19:17:08.117398 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of grid_connection_point:EnergyNode lists requirement 'energy_consumer' which will be fulfilled by connector_1:EvseManager->energy_grid:energy... 2024-10-08 19:17:08.117470 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of grid_connection_point:EnergyNode lists OPTIONAL requirement 'powermeter' which could not be fulfilled and will be ignored... 2024-10-08 19:17:08.117520 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of grid_connection_point:EnergyNode lists OPTIONAL requirement 'price_information' which could not be fulfilled and will be ignored... 2024-10-08 19:17:08.117612 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of iso15118_charger:EvseV2G lists requirement 'security' which will be fulfilled by evse_security:EvseSecurity->main:evse_security... 2024-10-08 19:17:08.117732 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of setup:Setup lists requirement 'store' which will be fulfilled by persistent_store:PersistentStore->main:kvs... 2024-10-08 19:17:08.117851 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: Manifest of token_provider:DummyTokenProvider lists requirement 'evse' which will be fulfilled by connector_1:EvseManager->evse:evse_manager... 2024-10-08 19:17:08.117933 [DEBG] energy_manager void Everest::Config::resolve_all_requirements() :: All module requirements resolved successfully... 2024-10-08 19:17:08.117983 [DEBG] energy_manager int Everest::ModuleLoader::initialize() :: Initializing framework for module energy_manager:EnergyManager... 2024-10-08 19:17:08.118034 [DEBG] energy_manager: Everest::MQTTAbstraction::MQTTAbstraction(const std::string&, const std::string&, const std::string&, const std::string&, const std::string&) :: initialized mqtt_abstraction 2024-10-08 19:17:08.118705 [DEBG] energy_manager: Everest::MQTTAbstractionImpl::MQTTAbstractionImpl(const std::string&, const std::string&, const std::string&, const std::string&) :: Initializing MQTT abstraction layer... 2024-10-08 19:17:08.123016 [DEBG] energy_manager: Everest::Everest::Everest(std::string, const Everest::Config&, bool, const std::string&, const std::string&, int, const std::string&, const std::string&, const std::string&, bool) :: Initializing EVerest framework... 2024-10-08 19:17:08.126998 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::register_handler(const std::string&, std::shared_ptr, QOS) :: Registering external MQTT handler 0x7fbd948465b8 on topic everest/ready 2024-10-08 19:17:08.127295 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::register_handler(const std::string&, std::shared_ptr, QOS) :: #handler[everest/ready] = 1 2024-10-08 19:17:08.127908 [DEBG] energy_manager: int Everest::ModuleLoader::initialize() :: Initializing module energy_manager:EnergyManager... 2024-10-08 19:17:08.128064 [DEBG] energy_manager: bool Everest::MQTTAbstractionImpl::connect() :: Connecting to MQTT broker: mqtt-server:1883 2024-10-08 19:17:08.129310 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::on_mqtt_connect() :: Connected to MQTT broker 2024-10-08 19:17:08.129378 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::on_mqtt_connect() :: Subscribing to needed MQTT topics... 2024-10-08 19:17:08.129408 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::on_mqtt_connect() :: Subscribing to everest/ready 2024-10-08 19:17:08.129453 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::publish(const std::string&, const std::string&, QOS) :: publishing to everest/energy_manager/metadata 2024-10-08 19:17:08.129826 [DEBG] energy_manager: std::vector module::everest_register(const nlohmann::json_abi_v3_11_2::json&) :: everest_register() called on module EnergyManager 2024-10-08 19:17:08.130423 [DEBG] energy_manager: static void module::LdEverest::init(ModuleConfigs, const ModuleInfo&) :: init() called on module EnergyManager 2024-10-08 19:17:08.130510 [DEBG] energy_manager: void Everest::Everest::subscribe_var(const Requirement&, const std::string&, const JsonCallback&) :: subscribing to var: energy_trunk:energy_flow_request 2024-10-08 19:17:08.133902 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::register_handler(const std::string&, std::shared_ptr, QOS) :: Registering subscribe handler 0x7fbd94848038 for variable energy_flow_request on topic everest/grid_connection_point/energy_grid/var 2024-10-08 19:17:08.134072 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::register_handler(const std::string&, std::shared_ptr, QOS) :: Subscribing to everest/grid_connection_point/energy_grid/var 2024-10-08 19:17:08.134163 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::register_handler(const std::string&, std::shared_ptr, QOS) :: #handler[everest/grid_connection_point/energy_grid/var] = 1 2024-10-08 19:17:08.134558 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::publish(const std::string&, const std::string&, QOS) :: publishing to everest/energy_manager/ready 2024-10-08 19:17:08.134726 [INFO] energy_manager: :: Module energy_manager initialized [663ms] 2024-10-08 19:17:08.323496 [INFO] grid_connection :: Module grid_connection_point initialized [684ms] 2024-10-08 19:17:08.355659 [INFO] evse_security:E :: Module evse_security initialized [774ms] 2024-10-08 19:17:08.391378 [INFO] connector_1:Evs :: Module connector_1 initialized [1019ms] 2024-10-08 19:17:08.620885 [INFO] iso15118_charge :: TCP server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:61341 2024-10-08 19:17:08.621374 [INFO] iso15118_charge :: TLS server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:64109 2024-10-08 19:17:08.621785 [INFO] iso15118_charge :: SDP socket setup succeeded 2024-10-08 19:17:08.622878 [INFO] iso15118_charge :: Module iso15118_charger initialized [693ms] 2024-10-08 19:17:08.696099 [INFO] setup:Setup :: Module setup initialized [694ms] 2024-10-08 19:17:08.769987 [INFO] persistent_stor :: Module persistent_store initialized [822ms] 2024-10-08 19:17:08.862841 [INFO] token_provider: :: Module token_provider initialized [602ms] 2024-10-08 19:17:08.939509 [INFO] token_validator :: Module token_validator initialized [567ms] 2024-10-08 19:17:09.269190 [INFO] manager :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [2556ms] πŸš™πŸš™πŸš™ 2024-10-08 19:17:09.270702 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::on_mqtt_message(std::shared_ptr) :: topic everest/ready starts with everest/ 2024-10-08 19:17:09.270969 [DEBG] energy_manager: void Everest::Everest::handle_ready(Everest::json) :: handle_ready: true 2024-10-08 19:17:09.271034 [DEBG] energy_manager: void Everest::Everest::handle_ready(Everest::json) :: Framework now ready to process events, calling module ready handler 2024-10-08 19:17:09.271074 [DEBG] energy_manager: static void module::LdEverest::ready() :: ready() called on module EnergyManager 2024-10-08 19:17:09.272906 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::on_mqtt_message(std::shared_ptr) :: topic everest/grid_connection_point/energy_grid/var starts with everest/ 2024-10-08 19:17:09.275939 [DEBG] energy_manager: Everest::Everest::subscribe_var(const Requirement&, const std::string&, const JsonCallback&):: :: Incoming grid_connection_point:EnergyNode->energy_grid:energy->energy_flow_request 2024-10-08 19:17:09.279594 [INFO] energy_manager: :: returning optimized values vector of length 0 2024-10-08 19:17:09.547001 [INFO] connector_1:Evs :: Ignoring BSP Event, BSP is not enabled yet. 2024-10-08 19:17:09.693358 [INFO] connector_1:Evs :: Max AC hardware capabilities: 32A/3ph 2024-10-08 19:17:09.708875 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::on_mqtt_message(std::shared_ptr) :: topic everest/grid_connection_point/energy_grid/var starts with everest/ 2024-10-08 19:17:09.710020 [DEBG] energy_manager: void Everest::MQTTAbstractionImpl::on_mqtt_message(std::shared_ptr) :: topic everest/grid_connection_point/energy_grid/var starts with everest/ 2024-10-08 19:17:09.710201 [DEBG] energy_manager: Everest::Everest::subscribe_var(const Requirement&, const std::string&, const JsonCallback&):: :: Incoming grid_connection_point:EnergyNode->energy_grid:energy->energy_flow_request 2024-10-08 19:17:09.711208 [DEBG] energy_manager: Everest::Everest::subscribe_var(const Requirement&, const std::string&, const JsonCallback&):: :: Incoming grid_connection_point:EnergyNode->energy_grid:energy->energy_flow_request 2024-10-08 19:17:09.736196 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Module energy_manager (pid: 14007) exited with status: 11. Terminating all modules. 2024-10-08 19:17:09.737938 [INFO] manager :: SIGTERM of child: api (pid: 14003) succeeded. 2024-10-08 19:17:09.738241 [INFO] manager :: SIGTERM of child: auth (pid: 14004) succeeded. 2024-10-08 19:17:09.738821 [INFO] manager :: SIGTERM of child: connector_1 (pid: 14005) succeeded. 2024-10-08 19:17:09.738919 [INFO] manager :: SIGTERM of child: connector_1_powerpath (pid: 14006) succeeded. 2024-10-08 19:17:09.738987 [INFO] manager :: SIGTERM of child: ev_manager (pid: 14014) succeeded. 2024-10-08 19:17:09.739211 [INFO] manager :: SIGTERM of child: evse_security (pid: 14015) succeeded. 2024-10-08 19:17:09.739424 [INFO] manager :: SIGTERM of child: grid_connection_point (pid: 14022) succeeded. 2024-10-08 19:17:09.739480 [INFO] manager :: SIGTERM of child: iso15118_car (pid: 14023) succeeded. 2024-10-08 19:17:09.739576 [INFO] manager :: SIGTERM of child: iso15118_charger (pid: 14024) succeeded. 2024-10-08 19:17:09.739653 [INFO] manager :: SIGTERM of child: persistent_store (pid: 14026) succeeded. 2024-10-08 19:17:09.739785 [INFO] manager :: SIGTERM of child: setup (pid: 14039) succeeded. 2024-10-08 19:17:09.739838 [INFO] manager :: SIGTERM of child: slac (pid: 14059) succeeded. 2024-10-08 19:17:09.739918 [INFO] manager :: SIGTERM of child: token_provider (pid: 14060) succeeded. 2024-10-08 19:17:09.739977 [INFO] manager :: SIGTERM of child: token_validator (pid: 14077) succeeded. 2024-10-08 19:17:09.740010 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Exiting manager. ```

This is either related to the MQTT subscription or to the returning optimized values vector of length 0. Let's find where they are and add additional logs...

The energy_manager module does not depend on anything else. Removing it from the config (by editing /ext/source/config/config-sil.yaml) results in not crashing, but multiple logs of 2024-10-08 19:27:53.014169 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0.

Modification + no crash logs ``` diff --git a/config/config-sil.yaml b/config/config-sil.yaml index fc1b561..d889d07 100644 --- a/config/config-sil.yaml +++ b/config/config-sil.yaml @@ -41,12 +41,6 @@ active_modules: - implementation_id: ev module_id: slac module: JsEvManager - energy_manager: - connections: - energy_trunk: - - implementation_id: energy_grid - module_id: grid_connection_point - module: EnergyManager connector_1: config_module: ac_enforce_hlc: false ``` Results in ``` 2024-10-08 19:30:09.554617 [INFO] manager :: ________ __ _ 2024-10-08 19:30:09.554804 [INFO] manager :: | ____\ \ / / | | 2024-10-08 19:30:09.554840 [INFO] manager :: | |__ \ \ / /__ _ __ ___ ___| |_ 2024-10-08 19:30:09.554895 [INFO] manager :: | __| \ \/ / _ \ '__/ _ \/ __| __| 2024-10-08 19:30:09.554964 [INFO] manager :: | |____ \ / __/ | | __/\__ \ |_ 2024-10-08 19:30:09.554998 [INFO] manager :: |______| \/ \___|_| \___||___/\__| 2024-10-08 19:30:09.555019 [INFO] manager :: 2024-10-08 19:30:09.555099 [INFO] manager :: Using MQTT broker mqtt-server:1883 2024-10-08 19:30:09.555224 [INFO] manager :: Telemetry enabled 2024-10-08 19:30:09.602156 [INFO] everest_ctrl :: Launching controller service on port 8849 2024-10-08 19:30:09.641611 [INFO] manager :: Loading config file at: /ext/source/config/config-sil.yaml 2024-10-08 19:30:10.023163 [INFO] manager :: Config loading completed in 425ms 2024-10-08 19:30:10.682242 [INFO] api:API :: Module api initialized [575ms] 2024-10-08 19:30:10.817918 [INFO] auth:Auth :: Module auth initialized [663ms] 2024-10-08 19:30:10.874906 [INFO] connector_1:Evs :: Module connector_1 initialized [671ms] 2024-10-08 19:30:10.997911 [INFO] evse_security:E :: Module evse_security initialized [649ms] 2024-10-08 19:30:11.148626 [INFO] grid_connection :: Module grid_connection_point initialized [739ms] 2024-10-08 19:30:11.285277 [INFO] iso15118_charge :: TCP server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:61341 2024-10-08 19:30:11.285407 [INFO] iso15118_charge :: TLS server on eth0 is listening on port [fe80::42:acff:fe12:3%25]:64109 2024-10-08 19:30:11.285472 [INFO] iso15118_charge :: SDP socket setup succeeded 2024-10-08 19:30:11.285716 [INFO] iso15118_charge :: Module iso15118_charger initialized [667ms] 2024-10-08 19:30:11.381741 [INFO] setup:Setup :: Module setup initialized [572ms] 2024-10-08 19:30:11.389333 [INFO] persistent_stor :: Module persistent_store initialized [680ms] 2024-10-08 19:30:11.602424 [INFO] token_validator :: Module token_validator initialized [535ms] 2024-10-08 19:30:11.630541 [INFO] token_provider: :: Module token_provider initialized [606ms] 2024-10-08 19:30:11.692212 [INFO] manager :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [2148ms] πŸš™πŸš™πŸš™ 2024-10-08 19:30:11.970278 [INFO] connector_1:Evs :: Ignoring BSP Event, BSP is not enabled yet. 2024-10-08 19:30:11.990807 [INFO] connector_1:Evs :: Max AC hardware capabilities: 32A/3ph 2024-10-08 19:30:12.045829 [INFO] connector_1:Evs :: AC HLC mode enabled. 2024-10-08 19:30:12.132367 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 0.000000, we get 0.000000 2024-10-08 19:30:12.175320 [INFO] connector_1:Evs :: πŸŒ€πŸŒ€πŸŒ€ Ready to start charging πŸŒ€πŸŒ€πŸŒ€ 2024-10-08 19:30:12.246384 [INFO] ev_manager:JsEv :: Unplug detected, restarting simulation. 2024-10-08 19:30:12.302832 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 0.000000, we get 0.000000 2024-10-08 19:30:22.084157 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:22.184785 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. ... 2024-10-08 19:30:51.882316 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:51.983196 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.084369 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.185132 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.286370 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.387298 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.488136 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.589127 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.690223 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.791307 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.892271 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:52.993228 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:53.094084 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:53.195310 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-08 19:30:53.296283 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. ```
Abby-Wheelis commented 1 month ago

I didn't work on this much yesterday, but I'm going to attempt to retrace the above steps today and see if I can get SIL working:

Created a docker compose file ``` version: "3.6" services: mqtt-server: image: ghcr.io/everest/everest-demo/mqtt-server:0.0.16 logging: driver: none manager: image: ghcr.io/us-joet/everest-demo/manager:cross-compile-charin-e2e-demo deploy: resources: limits: cpus: "1.0" memory: "1024mb" depends_on: - mqtt-server environment: - MQTT_SERVER_ADDRESS=mqtt-server entrypoint: "sh /ext/source/build/run-scripts/run-sil.sh" sysctls: - net.ipv6.conf.all.disable_ipv6=0 node-red: image: ghcr.io/everest/everest-demo/nodered:0.0.16 depends_on: - mqtt-server environment: - MQTT_SERVER_ADDRESS=mqtt-server - FLOWS=/config/config-sil-flow.json ports: - 1880:1880 sysctls: - net.ipv6.conf.all.disable_ipv6=0 ```
results ``` Attaching to everest-ac-demo-manager-1, everest-ac-demo-mqtt-server-1, everest-ac-demo-node-red-1 everest-ac-demo-mqtt-server-1 | 1728497602: mosquitto version 2.0.10 starting everest-ac-demo-mqtt-server-1 | 1728497602: Config loaded from /mosquitto/config/mosquitto.conf. everest-ac-demo-mqtt-server-1 | 1728497602: Opening ipv4 listen socket on port 1883. everest-ac-demo-mqtt-server-1 | 1728497602: Opening websockets listen socket on port 9001. everest-ac-demo-mqtt-server-1 | 1728497602: mosquitto version 2.0.10 running everest-ac-demo-manager-1 | 2024-10-09 18:13:25.730547 [INFO] manager :: ________ __ _ everest-ac-demo-manager-1 | 2024-10-09 18:13:25.731096 [INFO] manager :: | ____\ \ / / | | everest-ac-demo-manager-1 | 2024-10-09 18:13:25.731366 [INFO] manager :: | |__ \ \ / /__ _ __ ___ ___| |_ everest-ac-demo-manager-1 | 2024-10-09 18:13:25.731472 [INFO] manager :: | __| \ \/ / _ \ '__/ _ \/ __| __| everest-ac-demo-manager-1 | 2024-10-09 18:13:25.731577 [INFO] manager :: | |____ \ / __/ | | __/\__ \ |_ everest-ac-demo-manager-1 | 2024-10-09 18:13:25.731669 [INFO] manager :: |______| \/ \___|_| \___||___/\__| everest-ac-demo-manager-1 | 2024-10-09 18:13:25.731755 [INFO] manager :: everest-ac-demo-manager-1 | 2024-10-09 18:13:25.731841 [INFO] manager :: Using MQTT broker mqtt-server:1883 everest-ac-demo-manager-1 | 2024-10-09 18:13:25.731903 [INFO] manager :: Telemetry enabled everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | 2024-10-09 18:13:26.759619 [INFO] everest_ctrl :: Launching controller service on port 8849 everest-ac-demo-manager-1 | 2024-10-09 18:13:27.136424 [INFO] manager :: Loading config file at: /ext/source/config/config-sil.yaml everest-ac-demo-node-red-1 | everest-ac-demo-node-red-1 | > node-red-docker@2.2.3 start /usr/src/node-red everest-ac-demo-node-red-1 | > node $NODE_OPTIONS node_modules/node-red/red.js $FLOWS "--userDir" "/data" everest-ac-demo-node-red-1 | everest-ac-demo-manager-1 | 2024-10-09 18:13:29.647618 [INFO] manager :: Config loading completed in 2941ms everest-ac-demo-mqtt-server-1 | 1728497609: New connection from 172.21.0.3:56962 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497609: New client connected from 172.21.0.3:56962 as auto-E92F1DC6-6FE3-1BFA-1028-213CEB573A6D (p2, c1, k600). everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-node-red-1 | 9 Oct 18:13:36 - [info] everest-ac-demo-node-red-1 | everest-ac-demo-node-red-1 | Welcome to Node-RED everest-ac-demo-node-red-1 | =================== everest-ac-demo-node-red-1 | everest-ac-demo-node-red-1 | 9 Oct 18:13:36 - [info] Node-RED version: v2.2.3 everest-ac-demo-node-red-1 | 9 Oct 18:13:36 - [info] Node.js version: v14.19.3 everest-ac-demo-node-red-1 | 9 Oct 18:13:36 - [info] Linux 5.15.49-linuxkit-pr x64 LE everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-node-red-1 | 9 Oct 18:13:39 - [info] Loading palette nodes everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-node-red-1 | 9 Oct 18:13:46 - [info] Dashboard version 3.6.5 started at /ui everest-ac-demo-node-red-1 | 9 Oct 18:13:46 - [info] Settings file : /data/settings.js everest-ac-demo-node-red-1 | 9 Oct 18:13:46 - [info] Context store : 'default' [module=memory] everest-ac-demo-node-red-1 | 9 Oct 18:13:46 - [info] User directory : /data everest-ac-demo-node-red-1 | 9 Oct 18:13:46 - [warn] Projects disabled : editorTheme.projects.enabled=false everest-ac-demo-node-red-1 | 9 Oct 18:13:46 - [info] Flows file : /config/config-sil-flow.json everest-ac-demo-node-red-1 | 9 Oct 18:13:46 - [warn] everest-ac-demo-node-red-1 | everest-ac-demo-node-red-1 | --------------------------------------------------------------------- everest-ac-demo-node-red-1 | Your flow credentials file is encrypted using a system-generated key. everest-ac-demo-node-red-1 | everest-ac-demo-node-red-1 | If the system-generated key is lost for any reason, your credentials everest-ac-demo-node-red-1 | file will not be recoverable, you will have to delete it and re-enter everest-ac-demo-node-red-1 | your credentials. everest-ac-demo-node-red-1 | everest-ac-demo-node-red-1 | You should set your own key using the 'credentialSecret' option in everest-ac-demo-node-red-1 | your settings file. Node-RED will then re-encrypt your credentials everest-ac-demo-node-red-1 | file using your chosen key the next time you deploy a change. everest-ac-demo-node-red-1 | --------------------------------------------------------------------- everest-ac-demo-node-red-1 | everest-ac-demo-node-red-1 | 9 Oct 18:13:46 - [info] Server now running at http://127.0.0.1:1880/ everest-ac-demo-node-red-1 | 9 Oct 18:13:46 - [warn] Encrypted credentials not found everest-ac-demo-node-red-1 | 9 Oct 18:13:47 - [info] Starting flows everest-ac-demo-node-red-1 | 9 Oct 18:13:47 - [info] Started flows everest-ac-demo-mqtt-server-1 | 1728497627: New connection from 172.21.0.4:50544 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497627: New client connected from 172.21.0.4:50544 as nodered_04edd6a468ee1e80 (p2, c1, k60). everest-ac-demo-node-red-1 | 9 Oct 18:13:47 - [info] [mqtt-broker:fc8686af.48d178] Connected to broker: mqtt://mqtt-server:1883 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-mqtt-server-1 | 1728497642: New connection from 172.21.0.3:55446 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497642: New connection from 172.21.0.3:55454 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497642: New client connected from 172.21.0.3:55446 as auto-F90310CC-A311-DB17-D45E-104994B3628D (p2, c1, k600). everest-ac-demo-manager-1 | 2024-10-09 18:14:02.730219 [INFO] energy_manager: :: Module energy_manager initialized [29559ms] everest-ac-demo-mqtt-server-1 | 1728497642: New connection from 172.21.0.3:55468 on port 1883. everest-ac-demo-manager-1 | 2024-10-09 18:14:03.022573 [INFO] auth:Auth :: Module auth initialized [32300ms] everest-ac-demo-mqtt-server-1 | 1728497643: New client connected from 172.21.0.3:55468 as auto-EDEB49E9-E6BA-975F-68F2-3DA806016A94 (p2, c1, k600). everest-ac-demo-mqtt-server-1 | 1728497645: New connection from 172.21.0.3:55476 on port 1883. everest-ac-demo-manager-1 | 2024-10-09 18:14:05.924620 [INFO] api:API :: Module api initialized [35217ms] everest-ac-demo-mqtt-server-1 | 1728497645: New client connected from 172.21.0.3:55454 as auto-C1BA350A-19EC-37C6-CCCA-89D17D6B2345 (p2, c1, k600). everest-ac-demo-manager-1 | 2024-10-09 18:14:05.951630 [INFO] grid_connection :: Module grid_connection_point initialized [28831ms] everest-ac-demo-mqtt-server-1 | 1728497646: New client connected from 172.21.0.3:55476 as auto-45E8CF5D-B6A4-F725-9660-08636BB5CE3B (p2, c1, k600). everest-ac-demo-mqtt-server-1 | 1728497646: New connection from 172.21.0.3:55490 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497646: New connection from 172.21.0.3:55506 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497646: New client connected from 172.21.0.3:55506 as auto-50748FC0-83FD-A262-6BB5-AB2D01D1161F (p2, c1, k600). everest-ac-demo-manager-1 | 2024-10-09 18:14:07.129371 [INFO] connector_1:Evs :: Module connector_1 initialized [35182ms] everest-ac-demo-mqtt-server-1 | 1728497647: New connection from 172.21.0.3:55508 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497647: New client connected from 172.21.0.3:55490 as auto-AAA45E0C-3F2D-EFF0-96D9-605A27C17A78 (p2, c1, k600). everest-ac-demo-mqtt-server-1 | 1728497647: New connection from 172.21.0.3:55518 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497647: New client connected from 172.21.0.3:55508 as auto-ED791ACD-9F09-BBAF-B7A2-9E613A7D7676 (p2, c1, k600). everest-ac-demo-manager-1 | 2024-10-09 18:14:07.515556 [INFO] evse_security:E :: Module evse_security initialized [32846ms] everest-ac-demo-mqtt-server-1 | 1728497647: New client connected from 172.21.0.3:55518 as auto-79CF4172-74AC-CAC8-41A6-51A3F8046023 (p2, c1, k600). everest-ac-demo-mqtt-server-1 | 1728497648: New connection from 172.21.0.3:55534 on port 1883. everest-ac-demo-manager-1 | everest-ac-demo-manager-1 | 2024-10-09 18:14:08.649700 [INFO] iso15118_charge :: TCP server on eth0 is listening on port [fe80::42:acff:fe15:3%20]:61341 everest-ac-demo-manager-1 | everest-ac-demo-manager-1 | 2024-10-09 18:14:08.660639 [INFO] iso15118_charge :: TLS server on eth0 is listening on port [fe80::42:acff:fe15:3%20]:64109 everest-ac-demo-manager-1 | everest-ac-demo-manager-1 | 2024-10-09 18:14:08.663886 [INFO] iso15118_charge :: SDP socket setup succeeded everest-ac-demo-mqtt-server-1 | 1728497648: New connection from 172.21.0.3:55544 on port 1883. everest-ac-demo-manager-1 | 2024-10-09 18:14:08.712763 [INFO] iso15118_charge :: Module iso15118_charger initialized [26805ms] everest-ac-demo-mqtt-server-1 | 1728497648: New client connected from 172.21.0.3:55534 as auto-4FF4D217-498F-0F36-9EC2-301E9C287365 (p2, c1, k600). everest-ac-demo-manager-1 | 2024-10-09 18:14:09.139512 [INFO] persistent_stor :: Module persistent_store initialized [24359ms] everest-ac-demo-mqtt-server-1 | 1728497649: New client connected from 172.21.0.3:55544 as auto-93968409-368F-10D0-22EC-6D72973FA5A4 (p2, c1, k600). everest-ac-demo-mqtt-server-1 | 1728497649: New connection from 172.21.0.3:45728 on port 1883. everest-ac-demo-manager-1 | 2024-10-09 18:14:09.255409 [INFO] setup:Setup :: Module setup initialized [24006ms] everest-ac-demo-mqtt-server-1 | 1728497649: New client connected from 172.21.0.3:45728 as auto-C010CE61-A3F9-C1BC-7132-345145AAE221 (p2, c1, k600). everest-ac-demo-mqtt-server-1 | 1728497649: New connection from 172.21.0.3:45736 on port 1883. everest-ac-demo-manager-1 | 2024-10-09 18:14:09.920741 [INFO] token_validator :: Module token_validator initialized [16206ms] everest-ac-demo-mqtt-server-1 | 1728497649: New client connected from 172.21.0.3:45736 as auto-20E8D938-EE96-D62B-4F8F-F4496AD0D1B0 (p2, c1, k600). everest-ac-demo-mqtt-server-1 | 1728497649: New connection from 172.21.0.3:45740 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497650: New client connected from 172.21.0.3:45740 as auto-624DBB8D-FE33-160C-172B-D3221025429A (p2, c1, k600). everest-ac-demo-manager-1 | 2024-10-09 18:14:10.007274 [INFO] token_provider: :: Module token_provider initialized [18590ms] everest-ac-demo-mqtt-server-1 | 1728497650: New connection from 172.21.0.3:45744 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497650: New client connected from 172.21.0.3:45744 as auto-C720B9CB-F0DD-EB27-CDDB-B2214C34099F (p2, c1, k600). everest-ac-demo-mqtt-server-1 | 1728497651: New connection from 172.21.0.3:45750 on port 1883. everest-ac-demo-mqtt-server-1 | 1728497651: New client connected from 172.21.0.3:45750 as auto-967E15E8-47E7-0CDB-BBA5-CFBD31C15079 (p2, c1, k600). everest-ac-demo-manager-1 | 2024-10-09 18:14:11.517385 [INFO] manager :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [45876ms] πŸš™πŸš™πŸš™ everest-ac-demo-manager-1 | 2024-10-09 18:14:11.630480 [INFO] energy_manager: :: returning optimized values vector of length 0 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-manager-1 | 2024-10-09 18:14:11.817386 [INFO] connector_1:Evs :: Ignoring BSP Event, BSP is not enabled yet. everest-ac-demo-manager-1 | 2024-10-09 18:14:11.829195 [INFO] connector_1:Evs :: Max AC hardware capabilities: 32A/3ph everest-ac-demo-manager-1 | 2024-10-09 18:14:11.918592 [INFO] connector_1:Evs :: AC HLC mode enabled. everest-ac-demo-mqtt-server-1 | 1728497651: Client auto-F90310CC-A311-DB17-D45E-104994B3628D closed its connection. everest-ac-demo-manager-1 | 2024-10-09 18:14:11.962312 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Module energy_manager (pid: 31) exited with status: 11. Terminating all modules. everest-ac-demo-mqtt-server-1 | 1728497651: Client auto-C1BA350A-19EC-37C6-CCCA-89D17D6B2345 closed its connection. everest-ac-demo-manager-1 | 2024-10-09 18:14:11.976136 [INFO] manager :: SIGTERM of child: api (pid: 27) succeeded. everest-ac-demo-manager-1 | everest-ac-demo-manager-1 | 2024-10-09 18:14:11.977242 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 0.000000, we get 0.000000 everest-ac-demo-manager-1 | 2024-10-09 18:14:11.980402 [INFO] manager :: SIGTERM of child: auth (pid: 28) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:11.983639 [INFO] manager :: SIGTERM of child: connector_1 (pid: 29) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:11.984598 [INFO] manager :: SIGTERM of child: connector_1_powerpath (pid: 30) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:11.985979 [INFO] manager :: SIGTERM of child: ev_manager (pid: 32) succeeded. everest-ac-demo-mqtt-server-1 | 1728497651: Client auto-EDEB49E9-E6BA-975F-68F2-3DA806016A94 closed its connection. everest-ac-demo-mqtt-server-1 | 1728497651: Client auto-ED791ACD-9F09-BBAF-B7A2-9E613A7D7676 closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-79CF4172-74AC-CAC8-41A6-51A3F8046023 closed its connection. everest-ac-demo-manager-1 | 2024-10-09 18:14:11.995882 [INFO] manager :: SIGTERM of child: evse_security (pid: 38) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:12.002469 [INFO] manager :: SIGTERM of child: grid_connection_point (pid: 45) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:12.003484 [INFO] manager :: SIGTERM of child: iso15118_car (pid: 47) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:12.004507 [INFO] manager :: SIGTERM of child: iso15118_charger (pid: 48) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:12.005793 [INFO] manager :: SIGTERM of child: persistent_store (pid: 49) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:12.007245 [INFO] manager :: SIGTERM of child: setup (pid: 50) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:12.008815 [INFO] manager :: SIGTERM of child: slac (pid: 51) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:12.009870 [INFO] manager :: SIGTERM of child: token_provider (pid: 52) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:12.010966 [INFO] manager :: SIGTERM of child: token_validator (pid: 59) succeeded. everest-ac-demo-manager-1 | 2024-10-09 18:14:12.012122 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Exiting manager. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-624DBB8D-FE33-160C-172B-D3221025429A closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-93968409-368F-10D0-22EC-6D72973FA5A4 closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-C010CE61-A3F9-C1BC-7132-345145AAE221 closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-50748FC0-83FD-A262-6BB5-AB2D01D1161F closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-20E8D938-EE96-D62B-4F8F-F4496AD0D1B0 closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-45E8CF5D-B6A4-F725-9660-08636BB5CE3B closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-4FF4D217-498F-0F36-9EC2-301E9C287365 closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-C720B9CB-F0DD-EB27-CDDB-B2214C34099F closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-AAA45E0C-3F2D-EFF0-96D9-605A27C17A78 closed its connection. everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-967E15E8-47E7-0CDB-BBA5-CFBD31C15079 closed its connection. everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/message_queue.cpp.gcda:Merge mismatch for function 1151 everest-ac-demo-manager-1 | libgcov profiling error:/ext/source/build/_deps/everest-framework-build/lib/CMakeFiles/framework.dir/everest.cpp.gcda:Merge mismatch for function 4166 everest-ac-demo-mqtt-server-1 | 1728497652: Client auto-E92F1DC6-6FE3-1BFA-1028-213CEB573A6D closed its connection. everest-ac-demo-manager-1 exited with code 1 ```

Lots of libgcov Merge mismatch errors, but those seem safe to ignore, and erroring out the same way as this comment

So now I need to see if I can actually put in log statements and rebuild successfully

Abby-Wheelis commented 1 month ago

With the same docker compose file that @shankari was using, I now have things running, and I was able to add an arbitrary log statement and see it appear in the output.

Made the same modification to the config that was added to the comment above, and saw the same logs - I think I have the workflow working!

Curiously, can I get this to not crash on the hardware?

Copied everything over, including a the config file where I made the changes described in this comment

Crashing:

2024-10-10 17:27:53.451747 [ERRO] manager         void Everest::Config::resolve_all_requirements() :: Requirement 'slac' of module connector_1:EvseManager not fulfilled: required module slac:EvseSlac does not provide an implementation for 'evse'! 

Clearly need to update the config: the implementation_id for slac in the connections of connector_1 needed to be updated from evse to main to match the changes I made to slac

Config is still bad:

2024-10-10 17:35:02.753718 [ERRO] manager         void Everest::Config::resolve_all_requirements() :: Requirement 'slac' of module ev_manager:JsEvManager not fulfilled: required module slac:EvseSlac does not provide an implementation for 'ev'! 

Ironing out some more issues with the config with slac... I ended up commenting out the ev_manager since it was a simulator ...

Now getting a new error:

Full log ``` everest@umwcdbde:~ $ sudo /mnt/user_data/oct10/everest/bin/manager --conf /mnt/user_data/oct10/everest/etc/everest/config-sil-no-crash.yaml sudo: unable to resolve host umwcdbde: Name or service not known 2024-10-10 18:04:21.708669 [INFO] manager :: ________ __ _ 2024-10-10 18:04:21.709316 [INFO] manager :: | ____\ \ / / | | 2024-10-10 18:04:21.709522 [INFO] manager :: | |__ \ \ / /__ _ __ ___ ___| |_ 2024-10-10 18:04:21.709677 [INFO] manager :: | __| \ \/ / _ \ '__/ _ \/ __| __| 2024-10-10 18:04:21.709818 [INFO] manager :: | |____ \ / __/ | | __/\__ \ |_ 2024-10-10 18:04:21.709954 [INFO] manager :: |______| \/ \___|_| \___||___/\__| 2024-10-10 18:04:21.710092 [INFO] manager :: 2024-10-10 18:04:21.710225 [INFO] manager :: Using MQTT broker localhost:1883 2024-10-10 18:04:21.710378 [INFO] manager :: Telemetry enabled 2024-10-10 18:04:21.729341 [INFO] everest_ctrl :: Launching controller service on port 8849 2024-10-10 18:04:21.793955 [INFO] manager :: Loading config file at: /mnt/user_data/oct10/everest/etc/everest/config-sil-no-crash.yaml 2024-10-10 18:04:22.798660 [INFO] manager :: Config loading completed in 1085ms 2024-10-10 18:04:26.859927 [INFO] iso15118_charge :: TCP server on wlan0 is listening on port [fe80::f657:d2a1:20d:b660%3]:61341 2024-10-10 18:04:26.860832 [INFO] iso15118_charge :: TLS server on wlan0 is listening on port [fe80::f657:d2a1:20d:b660%3]:64109 2024-10-10 18:04:26.861134 [INFO] iso15118_charge :: SDP socket setup succeeded 2024-10-10 18:04:26.862320 [INFO] iso15118_charge :: Module iso15118_charger initialized [3764ms] 2024-10-10 18:04:27.033592 [INFO] grid_connection :: Module grid_connection_point initialized [4011ms] 2024-10-10 18:04:27.059999 [INFO] auth:Auth :: Module auth initialized [4167ms] 2024-10-10 18:04:27.089008 [INFO] setup:Setup :: Module setup initialized [3949ms] 2024-10-10 18:04:27.314232 [INFO] evse_security:E :: Module evse_security initialized [4312ms] 2024-10-10 18:04:27.445014 [INFO] token_provider: :: Module token_provider initialized [4270ms] 2024-10-10 18:04:27.530505 [INFO] yeti_driver_1:M :: Module yeti_driver_1 initialized [4284ms] 2024-10-10 18:04:27.532314 [INFO] token_validator :: Module token_validator initialized [4263ms] 2024-10-10 18:04:27.606586 [INFO] slac:EvseSlac :: Module slac initialized [4413ms] 2024-10-10 18:04:27.696871 [INFO] connector_1:Evs :: Module connector_1 initialized [4741ms] 2024-10-10 18:04:27.748893 [INFO] api:API :: Module api initialized [4843ms] 2024-10-10 18:04:27.797628 [ERRO] persistent_stor virtual void module::main::kvsImpl::init() :: Error opening PersistentStore database '"/home/everest/everest_persistent_store.db"': unable to open database file 2024-10-10 18:04:27.826710 [CRIT] persistent_stor int Everest::ModuleLoader::initialize() :: Caught top level std::exception: Dynamic exception type: std::runtime_error std::exception::what: Could not open PersistentStore database at provided path. 2024-10-10 18:04:27.887544 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Module persistent_store (pid: 2770) exited with status: 0. Terminating all modules. 2024-10-10 18:04:27.889306 [INFO] manager :: SIGTERM of child: api (pid: 2757) succeeded. 2024-10-10 18:04:27.892532 [INFO] manager :: SIGTERM of child: auth (pid: 2758) succeeded. 2024-10-10 18:04:27.896111 [INFO] manager :: SIGTERM of child: connector_1 (pid: 2759) succeeded. 2024-10-10 18:04:27.901961 [INFO] manager :: SIGTERM of child: connector_1_powerpath (pid: 2760) succeeded. 2024-10-10 18:04:27.907245 [INFO] manager :: SIGTERM of child: evse_security (pid: 2761) succeeded. 2024-10-10 18:04:27.907976 [INFO] manager :: SIGTERM of child: grid_connection_point (pid: 2762) succeeded. 2024-10-10 18:04:27.908567 [INFO] manager :: SIGTERM of child: iso15118_car (pid: 2763) succeeded. 2024-10-10 18:04:27.909286 [INFO] manager :: SIGTERM of child: iso15118_charger (pid: 2765) succeeded. 2024-10-10 18:04:27.909984 [INFO] manager :: SIGTERM of child: setup (pid: 2771) succeeded. 2024-10-10 18:04:27.910781 [INFO] manager :: SIGTERM of child: slac (pid: 2772) succeeded. 2024-10-10 18:04:27.911678 [INFO] manager :: SIGTERM of child: token_provider (pid: 2773) succeeded. 2024-10-10 18:04:27.912590 [INFO] manager :: SIGTERM of child: token_validator (pid: 2774) succeeded. 2024-10-10 18:04:27.913462 [INFO] manager :: SIGTERM of child: yeti_driver_1 (pid: 2775) succeeded. 2024-10-10 18:04:27.914281 [CRIT] manager int boot(const boost::program_options::variables_map&) :: Exiting manager. ```

The error is about the "PersistentStore database" - I remember seeing comments about the database in this thread, lets see where I can get referring back to those.

Config in current state: config-sil-no-crash.txt

shankari commented 1 month ago

@Abby-Wheelis what code changes (if any) did you have to make to get the SIL to work? We should keep track of that.

Abby-Wheelis commented 1 month ago

@shankari I did not do anything differently than you did, just ignored the warnings after modifying the config the way you described.

The only change I made before cross building and copying over to the hardware was to add the hardcoding as described before:

I would suggest hardcoding the value (caps.connector_type = types::evse_board_support::Connector_type::IEC62196Type2Cable;) found in modules/YetiDriver/board_support/evse_board_supportImpl.cpp into modules/MicroMegaWattBSP/board_support/evse_board_supportImpl.cpp

I commented out the parts of the config that referred to the PersistentStore, just to see what would happen, and am now back to the same string conversion error:

terminate called after throwing an instance of 'std::out_of_range'
  what():  No known string conversion for provided enum of type Connector_type
Abby-Wheelis commented 1 month ago

I just tried to add more log statements around where the new hardcoded assignment is, and in the initialization of those modules, but I'm still not seeing any of those log statements. Could I be doing something wrong in building? I have been following steps 6(c-e)&7 in this comment from Louis and the steps to create a release bundle and move it over in this comment from Shankari.

I'm concerned because I added logs to where "yeti driver" is initialized, but I'm not seeing any of the new log statements show up, I was hoping to narrow down where it tries to convert the Connector_type to a string, but no luck so far.

the-bay-kay commented 1 month ago

Let's see if we can't figure out this log discrepancy! (E.g.: changes are showing up within the SIL, but disappear after cross compilation. So, let's see if the issue is within the compilation, or the uploading / running on hardware).

I've successfully cross compiled using Abby et al.'s notes here, adding a log to /ext/source/modules/YetiDriver/YetiDriver.cpp before compilation. To see if this log shows up, we want to use objdump to inspect the compiled module. Unfortunately, running...

/bullseye-toolchain/crosstool/bin/armv8-rpi4-linux-gnueabihf-objdump/ -S /ext/source/build/modules/YetiDriver/YetiDriver

... results in a "file format not recognized" error. Inspecting the executable with file or readelf, we find that the YetiDriver file is an ELF 64-bit x86-64 LSB pie executable. This explains why we could inspect the final manager file (ELF 32-bit LSB executable, ARM), but not the intermediate elf. I was unable to find a copy of objdump within the toolchain that is meant for x86_64 (see logs below cut), so let's go ahead and add one to the toolchain...

ObjDumps in Toolchain ```bash /ext/source/build/modules/YetiDriver # find /bullseye-toolchain/ -name *objdump* /bullseye-toolchain/sysroot/usr/share/man/man1/arm-linux-gnueabihf-objdump.1.gz /bullseye-toolchain/sysroot/usr/share/man/man1/objdump.1.gz /bullseye-toolchain/sysroot/usr/bin/objdump /bullseye-toolchain/sysroot/usr/bin/arm-linux-gnueabihf-objdump /bullseye-toolchain/crosstool/bin/armv8-rpi4-linux-gnueabihf-objdump /bullseye-toolchain/crosstool/armv8-rpi4-linux-gnueabihf/bin/objdump ```
shankari commented 1 month ago

@the-bay-kay the modules in build-cross should be in arm format. The build directory is the original compiled version that we use in the SIL. build-cross contains the cross-compiled version that is copied over to the hardware.

the-bay-kay commented 1 month ago

... the modules in build-cross should be in arm format. The build directory is the original compiled version that we use in the SIL.

D'oh, right, thank you! That works OK with the objdump in our toolchain. I'm still not seeing the logs, or any line-by-line for that matter -- let me tweak some of the objdump settings... If all else fails I'll add a dummy function and look for its footprint in the assembly.

EDIT 2: Well, adding a function with bad syntax causes the build to fail, which would suggest that we are seeing changes in the cross compilation. Once I confirm this in the ARM code, I'll see what happens when we try to transfer the code over. (I also want to confirm that the changes occur between builds, let's do that before attempting to run on the VM)

objdump notes **EDIT**: `file YetiDriver` shows us... ```bash YetiDriver: ELF 32-bit LSB executable, ARM, EABI5 version 1 (GNU/Linux), dynamically linked, interpreter /lib/ld-linux-armhf.so.3, for GNU/Linux 3.2.0, not stripped ``` ... so, if the debug info is not stripped, why is -S not revealing the source code? Copying `YetiDriver.cpp` in the same directory doesn't help... I think we're missing the flag to include debug info during compilation. (e.g., "non-stripped" isn't enough). Let's check the Makefile...
the-bay-kay commented 1 month ago

Update: I've been able to successfully see changes made during the compilation process! The steps to reproduce may be found below the cut. Next, I plan to (i) look at the objdump of the full manager ELF, to confirm the logs are still there, and (ii) run this on an ARM VM, to confirm we see the logs.

Steps to check for Cross-Compilation Changes 1. Build as Abby & Co. described [here](https://github.com/everest/everest-demo/issues/51#issuecomment-2405713066) 2. Before adding changes to recompile, take a glance at the existing ARM assembly. Do so by running the following... ```bash /bullseye-toolchain/crosstool/bin/armv8-rpi4-linux-gnueabihf-objdump -S /ext/source/build-cross/modules/YetiDriver/YetiDriver > /ext/source/build-cross/ modules/YetiDriver/temp.log ``` ... and viewing it with... ```bash vi /ext/source/build-cross/modules/YetiDriver/temp.log ``` - For my tests, I decided to use YetiDriver arbitrarily, though any module should work. 3. Next, edit your files to add a function. In my case, I ran...| ```bash vim -O /ext/source/modules/YetiDriver/YetiDriver.cpp /ext/source/modules/YetiDriver/YetiDriver.hpp ``` ... and added a dummy function "YetiDriver::foo()" that prints out a log. Then, I called this function in the init() function. 4. Recompile as above -- e.g., run steps 6c-d of Louis' instructions [here](https://github.com/EVerest/everest-demo/issues/51#issuecomment-2163702427) 5. Repeating the objdump process described in step 2, you should be able to inspect the objdump logs and find your changes within this code! I've tested this a few times, and the changes have consistently appeared in the intermediate compiled modules.
shankari commented 1 month ago

@the-bay-kay that's great!

  1. Do you see the log statements or only the function name?
  2. Does it work for you to add a new function/log statement into the API module that @Abby-Wheelis used? Just to make sure that this is not specific to one module...
the-bay-kay commented 1 month ago
  1. Do you see the log statements are only the function name?

    • A: Only the function names. From what I understand, our cross-compilation doesn't run with the -g or -ggdb CMake flags -- since the debug info isn't included in the ELF file, we don't get the additional code. Looking at the file footprints...
      /ext/source/build-cross/modules/API/API: ELF 32-bit LSB executable, ARM, EABI5 version 1 (GNU/Linux), dynamically linked, interpreter /lib/ld-linux-armhf.so.3, for GNU/Linux 3.2.0, not stripped
      # ...
      /ext/source/build/modules/API/API: ELF 64-bit LSB pie executable, x86-64, version 1 (SYSV), dynamically linked, interpreter /lib/ld-musl-x86_64.so.1, with debug_info, not stripped  

      ... the native build includes debug info, but cross compile doesn't. We could probably set this flag somewhere in the source tree / make files, but I haven't dug too deeply.

  2. Yes! I just re-ran the test with /API/, and I'm seeing the function definition of the foo() I added. Checking the manager/ ELF next as a sanity check...

Abby-Wheelis commented 1 month ago

Update: I've been able to successfully see changes made during the compilation process!

I was able to replicate these steps and also see a function that I added in the logs!

the-bay-kay commented 1 month ago

When I go to check the manager...

/bullseye-toolchain/crosstool/bin/armv8-rpi4-linux-gnueabihf-objdump -S /ext/source/build-cross/dist/mnt/user_data/opt/everest/bin/manager > /tmp/temp.log

...I'm not seeing the signatures of the functions I added. They still appear within the intermediate phases' ARM code (API & YetiDriver) -- am I checking the wrong file? We should expect to see these signatures within the final manager, no? I deleted and re-compiled to ensure that I'm not looking at an old version...

I suppose there's a non-zero chance that my dummy files got optimized out via gcc (I don't know what flags we use, but IRRC, higher levels of optimization may remove "useless" code during optimization). From what I know about GCC, this shouldn't be an issue since we're defining a whole function and writing to the log stream.

Anyway, I'm glad to hear that you can replicate my build process @Abby-Wheelis ! LMK if those functions show up on the hardware -- I'll spend a bit more time digging into the manager's ASM, then I'll try running on the VM.

Abby-Wheelis commented 1 month ago

LMK if those functions show up on the hardware

Yes, after copying over I can see my function when I objdump /mnt/user_data/oct14/everest/libexec/everest/modules/YetiDriver/YetiDriver

FWIW I can't find it in /mnt/user_data/oct14/everest/bin/manager

It seems like I am updating the code, and the updates are copied over, so I'm going to add LOTS of logs and see if I can get anything to show up on hardware since it seems like the changes are persisting so maybe it's just crashing too early for the logs I tried to add earlier.

Edit: added EVLOG_error calls to several of the modules, none showing on the hardware

the-bay-kay commented 1 month ago

Good to know that we're seeing changes to the individual ELFs after copying! That rules that out, at least.

... added EVLOG_error calls to several of the modules, none showing on the hardware

Since we're not seeing the changes in manager, my hunch is that something hinky is going on during the final linking phase... I'll do some digging!

the-bay-kay commented 1 month ago

Let's trace the workflow to see how we compile manager...

The YetiDriver process defined in Makefile2 above seems to be the last mention of the module; likewise, nowhere in this section do I see a linking phase similar to YetiDriver.dir/build.make. I think this is all of the pieces, but I'm missing something -- let's read these closer and see if we can't find anything (If we can't, I may be barking up the wrong build tree...)

Abby-Wheelis commented 1 month ago

Investigate possibility of path being hardcoded:

1) running the manager in opt/ with the config that worked in SIL gives the same charger type error 2) removed opt/ and tried to run the manager in oct14/ (most recent cross-compiled copy) - failed immediately

$ sudo /mnt/user_data/oct14/everest/bin/manager --conf /mnt/user_data/oct14/everest/etc/everest/config-sil-no-crash-1.yaml 
sudo: unable to resolve host umwcdbde: Name or service not known
/mnt/user_data/oct14/everest/bin/manager: error while loading shared libraries: libframework.so.0.14.0: cannot open shared object file: No such file or directory

3) overwrite opt with contents of oct14

4) run it - does not crash -- seeing logs! (INIT API module is from me/new)

``` $ sudo /mnt/user_data/opt/everest/bin/manager --conf /mnt/user_data/opt/everest/etc/everest/config-sil-no-crash-1.yaml sudo: unable to resolve host umwcdbde: Name or service not known 2024-10-15 21:00:42.271515 [INFO] manager :: ________ __ _ 2024-10-15 21:00:42.272199 [INFO] manager :: | ____\ \ / / | | 2024-10-15 21:00:42.272321 [INFO] manager :: | |__ \ \ / /__ _ __ ___ ___| |_ 2024-10-15 21:00:42.272422 [INFO] manager :: | __| \ \/ / _ \ '__/ _ \/ __| __| 2024-10-15 21:00:42.272515 [INFO] manager :: | |____ \ / __/ | | __/\__ \ |_ 2024-10-15 21:00:42.272605 [INFO] manager :: |______| \/ \___|_| \___||___/\__| 2024-10-15 21:00:42.272694 [INFO] manager :: 2024-10-15 21:00:42.272779 [INFO] manager :: Using MQTT broker localhost:1883 2024-10-15 21:00:42.272877 [INFO] manager :: Telemetry enabled 2024-10-15 21:00:42.300282 [INFO] everest_ctrl :: Launching controller service on port 8849 2024-10-15 21:00:42.365175 [INFO] manager :: Loading config file at: /mnt/user_data/opt/everest/etc/everest/config-sil-no-crash-1.yaml 2024-10-15 21:00:43.289640 [INFO] manager :: Config loading completed in 1012ms 2024-10-15 21:00:46.990462 [INFO] auth:Auth :: Module auth initialized [3590ms] 2024-10-15 21:00:47.027747 [INFO] api:API :: INIT API module 2024-10-15 21:00:47.008461 [INFO] grid_connection :: Module grid_connection_point initialized [3469ms] 2024-10-15 21:00:47.105437 [INFO] evse_security:E :: Module evse_security initialized [3600ms] 2024-10-15 21:00:47.098469 [INFO] token_validator :: Module token_validator initialized [3490ms] 2024-10-15 21:00:47.120089 [INFO] iso15118_charge :: TCP server on eth1 is listening on port [fe80::122c:797c:de49:474a%3]:61341 2024-10-15 21:00:47.120978 [INFO] iso15118_charge :: TLS server on eth1 is listening on port [fe80::122c:797c:de49:474a%3]:641092024-10-15 21:00:47.108623 [INFO] token_provider: :: Module token_provider initialized [3500ms] 2024-10-15 21:00:47.121292 [INFO] iso15118_charge :: SDP socket setup succeeded 2024-10-15 21:00:47.124899 [INFO] iso15118_charge :: Module iso15118_charger initialized [3529ms] 2024-10-15 21:00:47.162707 [INFO] yeti_driver_1:M :: Initializing MMWBSP 2024-10-15 21:00:47.163305 [INFO] yeti_driver_1:M :: log message before the new connector hardcoding 2024-10-15 21:00:47.163458 [INFO] yeti_driver_1:M :: FILE WITH HARDCODED CONNECTOR TYPE! 2024-10-15 21:00:47.164208 [INFO] yeti_driver_1:M :: Module yeti_driver_1 initialized [3500ms] 2024-10-15 21:00:47.200673 [INFO] api:API :: Module api initialized [3825ms] 2024-10-15 21:00:47.256126 [INFO] slac:EvseSlac :: Module slac initialized [3648ms] 2024-10-15 21:00:47.584714 [INFO] connector_1:Evs :: Module connector_1 initialized [4112ms] 2024-10-15 21:00:49.067936 [INFO] manager :: πŸš™πŸš™πŸš™ All modules are initialized. EVerest up and running [6838ms] πŸš™πŸš™πŸš™ sh: 1: echo: echo: I/O error cobsDecode: Garbage detected 2024-10-15 21:00:49.169164 [INFO] slac:EvseSlac :: Starting the SLAC state machine 2024-10-15 21:00:49.170590 [INFO] slac:EvseSlac :: Qualcomm PLC Device Attributes: HW Platform: QCA7000 SW Platform: MAC Firmware: Build date: 1.2.5-0 ZC signal: Missing Line frequency: 50Hz 2024-10-15 21:00:49.270996 [INFO] slac:EvseSlac :: Entered Reset state 2024-10-15 21:00:49.271259 [INFO] slac:EvseSlac :: New NMK key: 43:37:4E:58:39:41:41:52:4D:4C:30:59:34:4E:47:50 2024-10-15 21:00:49.271811 [INFO] slac:EvseSlac :: Received CM_SET_KEY_CNF 2024-10-15 21:00:49.272551 [INFO] slac:EvseSlac :: Entered Idle state 2024-10-15 21:00:49.517694 [INFO] connector_1:Evs :: Max AC hardware capabilities: 6A/3ph 2024-10-15 21:00:49.577299 [INFO] connector_1:Evs :: AC HLC mode enabled. 2024-10-15 21:00:49.632972 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 0.000000, we get 0.000000 2024-10-15 21:00:49.683111 [INFO] connector_1:Evs :: πŸŒ€πŸŒ€πŸŒ€ Ready to start charging πŸŒ€πŸŒ€πŸŒ€ 2024-10-15 21:00:49.843083 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 0.000000, we get 0.000000 2024-10-15 21:00:59.603321 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-15 21:00:59.704037 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-15 21:00:59.804667 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-15 21:00:59.905352 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-15 21:01:00.006025 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-15 21:01:00.106656 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-15 21:01:00.207342 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-15 21:01:00.307978 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. 2024-10-15 21:01:00.408608 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. ```
shankari commented 1 month ago

Yay! I knew it had worked for me! Such a weird issue, and so annoying Now it's time to go to the lab and plug it in?!!

Abby-Wheelis commented 1 month ago

Now it's time to go to the lab and plug it in?!!

I think so!

There were a few parts of the config that I commented out, so I want to make sure we're testing with the "right" config, and debug anything else that comes up, but it does run, and we now know that code must be in /mnt/user_data/opt to be called as expected.

shankari commented 1 month ago

I think we are tracking that as a separate issue, so once you have checked over the configs, and confirmed that it consistently runs, we can go ahead and close this one (finally!!)

shankari commented 1 month ago

I will also point out that this only works if we disable the energy manager, which results in a max current of 0. Not sure if this will be a problem.

2024-10-15 23:09:56.883206 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 0.000000, we get 0.000000
2024-10-15 23:09:56.925627 [INFO] connector_1:Evs  :: πŸŒ€πŸŒ€πŸŒ€ Ready to start charging πŸŒ€πŸŒ€πŸŒ€

2024-10-15 23:09:57.009075 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: In ISO15118 charger impl, after updating AC max current to 0.000000, we get 0.000000
2024-10-15 23:10:06.898035 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0.
2024-10-15 23:10:06.998978 [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0.

In the SIL, if I enable the energy manager, it still crashes. @Abby-Wheelis can you confirm that this is true even on hardware?

Will spend a time-bounded effort tonight to see if I can get the energy manager to stop crashing so that we can try to actually send a real current value.

shankari commented 1 month ago

ok so the energy manager thing is weird. It looks like everything crashes ~ 10 seconds after the manager starts

I enabled debug logging in build/dist/etc/everest/default_logging.cfg and added several sleep statements to the main energy manager loop. new_sleep_statements.patch

If none of the sleep statements are in place, the energy manager crashes after 999 runs no_sleeps.log

$ grep "Run energy optimizer" /tmp/no_sleeps.log | wc -l
     999

If all the sleep statements are in place, the energy manager crashes after a single run all_sleeps.log

$ grep "Run energy optimizer" /tmp/all_sleeps.log | wc -l
       1

In both cases, the crash occurred after around 10 seconds

$ head -n1 /tmp/no_sleeps.log 
2024-10-16 00:40:36.868416 [INFO] manager          ::   ________      __                _   
$ tail -n1 /tmp/no_sleeps.log 
2024-10-16 00:40:42.411856 [CRIT] manager         int boot(const boost::program_options::variables_map&) :: Exiting manager.

$ head -n1 /tmp/all_sleeps.log 
2024-10-16 00:52:21.105189 [INFO] manager          ::   ________      __                _   
$ tail -n1 /tmp/all_sleeps.log 
2024-10-16 00:52:33.012974 [CRIT] manager         int boot(const boost::program_options::variables_map&) :: Exiting manager.

So I suspect this is related to some kind of threading/timing issue and not a particular issue with the code.

Note also that the optimizer doesn't actually return any values; in the no_sleep case, it consistently returns a vector of length 0. Can we just hack this to set the energy limit once and disable the thread? that would be the most surgical change...

shankari commented 1 month ago

Looking at logs from a prior successful SIL run (non-cross-compiled), I can see that the optimizer returns a vector with a single value

2024-07-17 22:26:45.186727 [INFO] energy_manager:  ::                                NO TRADE
2024-07-17 22:26:45.186918 [INFO] energy_manager:  :: Sending enfored limits (import) to :evse_manager_1 {
    "ac_max_current_A": 32.0
}
2024-07-17 22:26:45.186986 [INFO] energy_manager:  :: returning optimized values vector of length 1
2024-07-17 22:26:45.187077 [INFO] energy_manager:  :: evse_manager_1 Enforce limits 32A -9999W

let's try to return that value and see how it goes.

shankari commented 1 month ago

After the changes, I see

2024-10-16 01:40:09.569465 [INFO] energy_manager:  :: about to init globals again
2024-10-16 01:40:09.570124 [INFO] energy_manager:  :: about to lock the energy mutex
2024-10-16 01:40:09.570222 [INFO] energy_manager:  :: launched the mutex
2024-10-16 01:40:09.570526 [INFO] energy_manager:  :: returning optimized values vector of length 1
2024-10-16 01:40:09.570684 [INFO] energy_manager:  :: ran optimizer in the ready loop, got values 1
2024-10-16 01:40:09.570825 [INFO] energy_manager:  :: my_fake_uuid Enforce limits 32A -9999W 

And then a crash

Will fix the UUID to evse_manager_1, but the issue is clearly not with the values returned but with the thread. Trying to set the values once and not launching the thread at all...