search

EVerest / libocpp

C++ implementation of the Open Charge Point Protocol
Apache License 2.0
83 stars 42 forks source link

Exception during start: ComponentVariable that doesn't exist in the device model storage #676

Closed lategoodbye closed 1 month ago

lategoodbye commented 1 month ago

OCPP Version

OCPP2.0.1

Describe the bug

We noticed the following issue with our Tarragon platform and EVerest core 2024.05. In case we connect an EV (CP state B) and reboot the charge controller, the following error occur after reboot:

2024-06-18T09:09:05.489009+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Established connection to database: "/var/lib/everest/ocpp201/cp.db"
2024-06-18T09:09:05.506223+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Established connection to device model database successfully: "/var/lib/everest/ocpp201/cp.db"
2024-06-18T09:09:05.546179+0200 tarragon manager[2616]: [INFO] connector_1:Evs  :: Max AC hardware capabilities: 32A/3ph
2024-06-18T09:09:05.709111+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Successfully retrieved Device Model from DeviceModelStorage
2024-06-18T09:09:05.714099+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Established connection to database: "/var/lib/everest/ocpp201/cp.db"
2024-06-18T09:09:05.716295+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Target version: 1, current version: 1
2024-06-18T09:09:05.717703+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: No migrations to apply since versions match
2024-06-18T09:09:05.725131+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Successfully closed database: "/var/lib/everest/ocpp201/cp.db"    
2024-06-18T09:09:05.728309+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Established connection to database: "/var/lib/everest/ocpp201/cp.db"
2024-06-18T09:09:05.748972+0200 tarragon manager[2628]: [INFO] tarragon_pluglo  :: Plug is unlocked. Feedback voltage: 3000 mV
2024-06-18T09:09:05.914661+0200 tarragon manager[2616]: [INFO] connector_1:Evs  :: 🌀🌀🌀 Ready to start charging 🌀🌀🌀
2024-06-18T09:09:06.104471+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: EVSE 1 ready.
2024-06-18T09:09:06.125193+0200 tarragon manager[2627]: [INFO] tarragon_bsp:Cb  :: handle_enable: Setting new duty cycle of 100.00%
2024-06-18T09:09:06.136793+0200 tarragon manager[2627]: [INFO] tarragon_bsp:Cb  :: CP state change from PowerOn to B, U_CP+: 8861 mV, U_CP-: 7 mV
2024-06-18T09:09:06.148636+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Logging OCPP messages to log file: /tmp/everest_ocpp_logs/2024-06-18T07:09:06.143Z.log
2024-06-18T09:09:06.153196+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Logging OCPP messages to html file: /tmp/everest_ocpp_logs/2024-06-18T07:09:06.143Z.html
2024-06-18T09:09:06.157146+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: Logging SecurityEvents to file
2024-06-18T09:09:06.467754+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: EVSE 2 ready.
2024-06-18T09:09:06.470767+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: TxStartPoints from device model: EVConnected
2024-06-18T09:09:06.483641+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: TxStopPoints from device model: EVConnected
2024-06-18T09:09:06.634763+0200 tarragon manager[2622]: [INFO] ocpp:OCPP201     :: All EVSE ready. Starting OCPP2.0.1 service
2024-06-18T09:09:06.998121+0200 tarragon manager[2628]: [INFO] tarragon_pluglo  :: Plug is locked. Feedback voltage: 624 mV
2024-06-18T09:09:07.056269+0200 tarragon manager[2627]: [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
2024-06-18T09:09:07.483672+0200 tarragon manager[2622]: [ERRO] ocpp:OCPP201    void ocpp::DateTimeImpl::from_rfc3339(const string&) :: Timepoint string parsing failed. Could not convert: "" into DateTime.
2024-06-18T09:09:07.552378+0200 tarragon manager[2622]: [ERRO] ocpp:OCPP201    virtual ocpp::common::SQLiteStatement::~SQLiteStatement() :: Error finalizing statement: database is locked
2024-06-18T09:09:07.562300+0200 tarragon manager[2622]: [CRIT] ocpp:OCPP201    T ocpp::v201::DeviceModel::get_value(const ocpp::v201::RequiredComponentVariable&, const ocpp::v201::AttributeEnum&) [with T = int] :: Directly requested value for ComponentVariable that doesn't exist in the device model storage: {
2024-06-18T09:09:07.562300+0200 tarragon manager[2622]:     "component": {
2024-06-18T09:09:07.562300+0200 tarragon manager[2622]:         "name": "OCPPCommCtrlr"
2024-06-18T09:09:07.562300+0200 tarragon manager[2622]:     },
2024-06-18T09:09:07.562300+0200 tarragon manager[2622]:     "variable": {
2024-06-18T09:09:07.562300+0200 tarragon manager[2622]:         "name": "RetryBackOffWaitMinimum"
2024-06-18T09:09:07.562300+0200 tarragon manager[2622]:     }
2024-06-18T09:09:07.587282+0200 tarragon manager[2622]: }
2024-06-18T09:09:07.587282+0200 tarragon manager[2622]: [ERRO] ocpp:OCPP201    T ocpp::v201::DeviceModel::get_value(const ocpp::v201::RequiredComponentVariable&, const ocpp::v201::AttributeEnum&) [with T = int] :: Directly requested value for ComponentVariable that doesn't exist in the device model storage.
2024-06-18T09:09:07.587282+0200 tarragon manager[2622]: terminate called after throwing an instance of 'boost::wrapexcept<boost::exception_detail::error_info_injector<std::runtime_error> >'
2024-06-18T09:09:07.587282+0200 tarragon manager[2622]:   what():  Directly requested value for ComponentVariable that doesn't exist in the device model storage.
2024-06-18T09:09:07.626857+0200 tarragon manager[2627]: [INFO] tarragon_bsp:Cb  :: Read PP ampacity value: A_20 (U_PP: 1554 mV)
2024-06-18T09:09:07.661646+0200 tarragon manager[2590]: [CRIT] manager         int boot(const boost::program_options::variables_map&) :: Module ocpp (pid: 2622) exited with status: 6. Terminating all modules.
2024-06-18T09:09:07.693367+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: MCRRFIDTokenProvider0 (pid: 2612) succeeded.    
2024-06-18T09:09:07.693367+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: api_1 (pid: 2613) succeeded.
2024-06-18T09:09:07.693367+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: api_2 (pid: 2614) succeeded.
2024-06-18T09:09:07.789242+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: auth (pid: 2615) succeeded.
2024-06-18T09:09:07.789242+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: connector_1 (pid: 2616) succeeded.
2024-06-18T09:09:07.789242+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: connector_2 (pid: 2617) succeeded.
2024-06-18T09:09:07.789242+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: energy_manager (pid: 2618) succeeded.
2024-06-18T09:09:07.789242+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: evse_security (pid: 2619) succeeded.
2024-06-18T09:09:07.789242+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: grid_connection_point (pid: 2620) succeeded.    
2024-06-18T09:09:07.827863+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: hmiled (pid: 2621) succeeded.
2024-06-18T09:09:07.827863+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: powermeter (pid: 2623) succeeded.
2024-06-18T09:09:07.827863+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: serialcommhub_x7 (pid: 2624) succeeded.
2024-06-18T09:09:07.876338+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: system (pid: 2625) succeeded.
2024-06-18T09:09:07.876338+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: system_aggregator (pid: 2626) succeeded.        
2024-06-18T09:09:07.876338+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: tarragon_bsp (pid: 2627) succeeded.
2024-06-18T09:09:07.876338+0200 tarragon manager[2590]: [INFO] manager          :: SIGTERM of child: tarragon_pluglock (pid: 2628) succeeded.        
2024-06-18T09:09:07.876338+0200 tarragon manager[2590]: [CRIT] manager         int boot(const boost::program_options::variables_map&) :: Exiting manager.
2024-06-18T09:09:07.940648+0200 tarragon systemd[1]: everest.service: Main process exited, code=exited, status=1/FAILURE
2024-06-18T09:09:07.941791+0200 tarragon systemd[1]: everest.service: Killing process 2592 (controller) with signal SIGKILL.
2024-06-18T09:09:07.965318+0200 tarragon systemd[1]: everest.service: Failed with result 'exit-code'.

The change #675 has already applied.

To Reproduce

Anything else?

No response

Pietfried commented 1 month ago

Hi @lategoodbye , how is your DeviceModelDatabasePath in the OCPP201 module configured? Can you check if the database its pointing to is initialized and contains values?

lategoodbye commented 1 month ago

As part of the logs the database is located at "/var/lib/everest/ocpp201/cp.db".

How can i check for the relevant values (in terms of which SQL statement to use)?

Pietfried commented 1 month ago

As part of the logs the database is located at "/var/lib/everest/ocpp201/cp.db".

How can i check for the relevant values (in terms of which SQL statement to use)?

OCPP201 uses two databases, one for the device model and one for core functional blocks (AuthorizationCache, LocalAuthorizationCache, etc). cp.db is the core database. So please check your configuration of theDeviceModelDatabasePath of the OCPP201 module. It looks like its not initialized.

lategoodbye commented 1 month ago

Here are the settings:

ocpp:
    module: OCPP201
    config_module:
      CoreDatabasePath: /var/lib/everest/ocpp201
      DeviceModelDatabasePath: /var/lib/everest/ocpp201/cp.db

According to the logs both seems to use the same name. Is this problematic?

Sorry, i don't have direct access, because it's on our customers EVSE.

Pietfried commented 1 month ago

Here are the settings:

ocpp:
    module: OCPP201
    config_module:
      CoreDatabasePath: /var/lib/everest/ocpp201
      DeviceModelDatabasePath: /var/lib/everest/ocpp201/cp.db

According to the logs both seems to use the same name. Is this problematic?

Sorry, i don't have direct access, because it's on our customers EVSE.

Thanks for providing the config and sorry I missed this in the logs because of the same name. This is indeed problematic! The core database has a hardcoded name of cp.db and for the device model database you can provide a full path. We will need to harmonize this.

For resolving the issue now you should try to use a different file name for DeviceModelDatabasePath

lategoodbye commented 1 month ago

Thanks, i forwarded it to the customer.

lategoodbye commented 1 month ago

Here are my suggestions to avoid this issue: