Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DateTime parsing exception prevents initial EVerest start #678

Closed
lategoodbye opened this issue Jun 19, 2024 · 7 comments
Closed

DateTime parsing exception prevents initial EVerest start #678

lategoodbye opened this issue Jun 19, 2024 · 7 comments
Assignees

Comments

@lategoodbye
Copy link

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 occurs only once after reboot:

2024-06-19T08:38:11.177805+0200 tarragon systemd[1]: Started EVerest.
2024-06-19T08:38:11.381615+0200 tarragon manager[402]: [INFO] manager          ::   ________      __                _
2024-06-19T08:38:11.388031+0200 tarragon manager[402]: [INFO] manager          ::  |  ____\ \    / /               | |
2024-06-19T08:38:11.388031+0200 tarragon manager[402]: [INFO] manager          ::  | |__   \ \  / /__ _ __ ___  ___| |_
2024-06-19T08:38:11.388031+0200 tarragon manager[402]: [INFO] manager          ::  |  __|   \ \/ / _ \ '__/ _ \/ __| __|
2024-06-19T08:38:11.388031+0200 tarragon manager[402]: [INFO] manager          ::  | |____   \  /  __/ | |  __/\__ \ |_
2024-06-19T08:38:11.388031+0200 tarragon manager[402]: [INFO] manager          ::  |______|   \/ \___|_|  \___||___/\__|
2024-06-19T08:38:11.388031+0200 tarragon manager[402]: [INFO] manager          ::
2024-06-19T08:38:11.388031+0200 tarragon manager[402]: [INFO] manager          :: Using MQTT broker localhost:1883
2024-06-19T08:38:11.500763+0200 tarragon manager[403]: [INFO] everest_ctrl     :: Launching controller service on port 8849
2024-06-19T08:38:11.561664+0200 tarragon manager[402]: [INFO] manager          :: Loading config file at: /etc/everest/lesbos_left_dual_ocpp201.yaml
2024-06-19T08:38:13.160226+0200 tarragon manager[402]: [INFO] manager          :: Config loading completed in 1760ms
2024-06-19T08:39:01.816076+0200 tarragon manager[431]: [INFO] energy_manager:  :: Module energy_manager initialized [47532ms]
2024-06-19T08:39:02.106351+0200 tarragon manager[437]: [INFO] serialcommhub_x  :: Module serialcommhub_x7 initialized [47214ms]
2024-06-19T08:39:02.156468+0200 tarragon manager[430]: [INFO] connector_2:Sat  :: Connecting to SatelliteAgent on 192.168.1.11:4129...
2024-06-19T08:39:02.270787+0200 tarragon manager[438]: [INFO] system:CbSystem  :: Module system initialized [47156ms]
2024-06-19T08:39:02.315870+0200 tarragon manager[436]: [INFO] powermeter:Powe  :: Powermeter driver for Iskra WM3M4 & WM3M4C (version: 0.2)
2024-06-19T08:39:02.379230+0200 tarragon manager[436]: [INFO] powermeter:Powe  :: Module powermeter initialized [47678ms]
2024-06-19T08:39:02.465866+0200 tarragon manager[433]: [INFO] grid_connection  :: Module grid_connection_point initialized [48060ms]
2024-06-19T08:39:02.495841+0200 tarragon manager[432]: [INFO] evse_security:E  :: Module evse_security initialized [48209ms]
2024-06-19T08:39:02.706102+0200 tarragon manager[428]: [INFO] auth:Auth        :: Module auth initialized [48783ms]
2024-06-19T08:39:02.826712+0200 tarragon manager[439]: [INFO] system_aggregat  :: Module system_aggregator initialized [47655ms]
2024-06-19T08:39:02.895874+0200 tarragon manager[441]: [INFO] tarragon_pluglo  :: chargebyte's Tarragon driver for plug lock control (version: 0.10.0)
2024-06-19T08:39:02.901682+0200 tarragon manager[441]: [INFO] tarragon_pluglo  :: Module tarragon_pluglock initialized [29416ms]
2024-06-19T08:39:02.975050+0200 tarragon manager[442]: [INFO] token_provider_  :: Module token_provider_1 initialized [29422ms]
2024-06-19T08:39:02.996776+0200 tarragon manager[443]: [INFO] token_provider_  :: Module token_provider_2 initialized [29319ms]
2024-06-19T08:39:03.026850+0200 tarragon manager[427]: [INFO] api_2:API        :: Module api_2 initialized [49279ms]
2024-06-19T08:39:03.059298+0200 tarragon manager[426]: [INFO] api_1:API        :: Module api_1 initialized [49290ms]
2024-06-19T08:39:03.149498+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: Control Pilot Observation Thread started
2024-06-19T08:39:03.245855+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: Primary contactor feedback type: 'nc'
2024-06-19T08:39:03.257149+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: chargebyte's Hardware EVerest Modules (version: 0.10.0)
2024-06-19T08:39:03.259495+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: Module tarragon_bsp initialized [29731ms]
2024-06-19T08:39:03.266807+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: Contactor Handling Thread started
2024-06-19T08:39:03.346667+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Module ocpp initialized [47871ms]
2024-06-19T08:39:03.709766+0200 tarragon manager[434]: [INFO] hmiled:GpioRgbL  :: The EVerest RGB LED driver (version: 0.5.0)
2024-06-19T08:39:03.715731+0200 tarragon manager[434]: [INFO] hmiled:GpioRgbL  :: Using GPIO LED control
2024-06-19T08:39:03.793883+0200 tarragon manager[434]: [INFO] hmiled:GpioRgbL  :: Launching blink timer thread
2024-06-19T08:39:03.883254+0200 tarragon manager[434]: [INFO] hmiled:GpioRgbL  :: No OCPP module is connected.
2024-06-19T08:39:03.884422+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: Module connector_1 initialized [49699ms]
2024-06-19T08:39:03.917110+0200 tarragon manager[434]: [INFO] hmiled:GpioRgbL  :: Module hmiled initialized [49116ms]
2024-06-19T08:39:14.313492+0200 tarragon manager[430]: [INFO] connector_2:Sat  :: Module connector_2 initialized [60119ms]
2024-06-19T08:39:14.324509+0200 tarragon manager[402]: [INFO] manager          :: 🚙🚙🚙 All modules are initialized. EVerest up and running [62964ms] 🚙🚙🚙
2024-06-19T08:39:14.567709+0200 tarragon manager[434]: [INFO] hmiled:GpioRgbL  :: Our connector is connector#1
2024-06-19T08:39:14.617362+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: Read PP ampacity value: A_13 (U_PP: 2083 mV)
2024-06-19T08:39:14.624403+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: Proximity Pilot Observation Thread started
2024-06-19T08:39:14.710735+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: Max AC hardware capabilities: 16A/3ph
2024-06-19T08:39:14.906841+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Established connection to database: "/var/lib/everest/ocpp201/device_model_storage.db"
2024-06-19T08:39:14.917190+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Established connection to device model database successfully: "/var/lib/everest/ocpp201/device_model_storage.db"
2024-06-19T08:39:14.963836+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: 🌀🌀🌀 Ready to start charging 🌀🌀🌀
2024-06-19T08:39:14.963836+0200 tarragon manager[441]: [INFO] tarragon_pluglo  :: Plug is unlocked. Feedback voltage: 3000 mV
2024-06-19T08:39:15.088790+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Successfully retrieved Device Model from DeviceModelStorage
2024-06-19T08:39:15.108398+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Established connection to database: "/var/lib/everest/ocpp201/cp.db"
2024-06-19T08:39:15.111137+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: EVSE 2 ready.
2024-06-19T08:39:15.114962+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Target version: 1, current version: 1
2024-06-19T08:39:15.120499+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: No migrations to apply since versions match
2024-06-19T08:39:15.125913+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Successfully closed database: "/var/lib/everest/ocpp201/cp.db"
2024-06-19T08:39:15.125913+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Established connection to database: "/var/lib/everest/ocpp201/cp.db"
2024-06-19T08:39:15.140627+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: EVSE 1 ready.
2024-06-19T08:39:15.201357+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: handle_enable: Setting new duty cycle of 100.00%
2024-06-19T08:39:15.216762+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: CP state change from PowerOn to B, U_CP+: 8900 mV, U_CP-: 55 mV
2024-06-19T08:39:15.526979+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Logging OCPP messages to log file: /tmp/everest_ocpp_logs/2024-06-19T06:39:15.523Z.log
2024-06-19T08:39:15.529035+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Logging OCPP messages to html file: /tmp/everest_ocpp_logs/2024-06-19T06:39:15.523Z.html
2024-06-19T08:39:15.530960+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Logging SecurityEvents to file
2024-06-19T08:39:15.730327+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: TxStartPoints from device model: PowerPathClosed
2024-06-19T08:39:15.736936+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: TxStopPoints from device model: EVConnected,Authorized
2024-06-19T08:39:15.889906+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: All EVSE ready. Starting OCPP2.0.1 service
2024-06-19T08:39:16.019908+0200 tarragon manager[441]: [INFO] tarragon_pluglo  :: Plug is locked. Feedback voltage: 626 mV
2024-06-19T08:39:16.090641+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
2024-06-19T08:39:16.300546+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: SYS  Session logging started.
2024-06-19T08:39:16.307566+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: EVSE IEC Session Started: EVConnected
2024-06-19T08:39:16.369994+0200 tarragon manager[442]: [INFO] token_provider_  :: Publishing new dummy token: {
2024-06-19T08:39:16.369994+0200 tarragon manager[442]:     "type": "ISO14443",
2024-06-19T08:39:16.369994+0200 tarragon manager[442]:     "value": "deadbeef"
2024-06-19T08:39:16.369994+0200 tarragon manager[442]: } (RFID)
2024-06-19T08:39:16.449866+0200 tarragon manager[428]: [INFO] auth:Auth        :: Received new token: {
2024-06-19T08:39:16.449866+0200 tarragon manager[428]:     "authorization_type": "RFID",
2024-06-19T08:39:16.449866+0200 tarragon manager[428]:     "id_token": {
2024-06-19T08:39:16.449866+0200 tarragon manager[428]:         "type": "ISO14443",
2024-06-19T08:39:16.449866+0200 tarragon manager[428]:         "value": "deadbeef"
2024-06-19T08:39:16.449866+0200 tarragon manager[428]:     }
2024-06-19T08:39:16.474570+0200 tarragon manager[428]: }
2024-06-19T08:39:16.485316+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: Read PP ampacity value: A_13 (U_PP: 2082 mV)
2024-06-19T08:39:16.600274+0200 tarragon manager[435]: [INFO] ocpp:OCPP201     :: Found valid entry in AuthCache
2024-06-19T08:39:16.631705+0200 tarragon manager[428]: [INFO] auth:Auth        :: Providing authorization to connector#1
2024-06-19T08:39:16.721660+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: EVSE IEC EIM Authorization received
2024-06-19T08:39:16.781533+0200 tarragon manager[428]: [INFO] auth:Auth        :: Result for token: deadbeef: ACCEPTED
2024-06-19T08:39:16.831136+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: EVSE IEC Transaction Started (0 kWh)
2024-06-19T08:39:16.834979+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: EVSE IEC AC mode, HLC disabled. We are in X1 so we can go directly to nominal PWM.
2024-06-19T08:39:16.842783+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: EVSE IEC Charger state: Wait for Auth->PrepareCharging
2024-06-19T08:39:16.861276+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: EVSE IEC Charger state: PrepareCharging->Wait for energy
2024-06-19T08:39:16.870437+0200 tarragon manager[429]: [INFO] connector_1:Evs  :: EVSE IEC Set PWM Off
2024-06-19T08:39:17.008917+0200 tarragon manager[435]: [ERRO] ocpp:OCPP201    void ocpp::DateTimeImpl::from_rfc3339(const string&) :: Timepoint string parsing failed. Could not convert: "" into DateTime.
2024-06-19T08:39:17.208134+0200 tarragon manager[402]: [CRIT] manager         int boot(const boost::program_options::variables_map&) :: Module ocpp (pid: 435) exited with status: 11. Terminating all modules.
2024-06-19T08:39:17.239382+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: api_1 (pid: 426) succeeded.
2024-06-19T08:39:17.240428+0200 tarragon manager[440]: [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
2024-06-19T08:39:17.319971+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: api_2 (pid: 427) succeeded.
2024-06-19T08:39:17.319971+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: auth (pid: 428) succeeded.
2024-06-19T08:39:17.319971+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: connector_1 (pid: 429) succeeded.
2024-06-19T08:39:17.319971+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: connector_2 (pid: 430) succeeded.
2024-06-19T08:39:17.319971+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: energy_manager (pid: 431) succeeded.
2024-06-19T08:39:17.319971+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: evse_security (pid: 432) succeeded.
2024-06-19T08:39:17.319971+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: grid_connection_point (pid: 433) succeeded.
2024-06-19T08:39:17.388560+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: hmiled (pid: 434) succeeded.
2024-06-19T08:39:17.388560+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: powermeter (pid: 436) succeeded.
2024-06-19T08:39:17.388560+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: serialcommhub_x7 (pid: 437) succeeded.
2024-06-19T08:39:17.388560+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: system (pid: 438) succeeded.
2024-06-19T08:39:17.388560+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: system_aggregator (pid: 439) succeeded.
2024-06-19T08:39:17.388560+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: tarragon_bsp (pid: 440) succeeded.
2024-06-19T08:39:17.388560+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: tarragon_pluglock (pid: 441) succeeded.
2024-06-19T08:39:17.388560+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: token_provider_1 (pid: 442) succeeded.
2024-06-19T08:39:17.415735+0200 tarragon manager[402]: [INFO] manager          :: SIGTERM of child: token_provider_2 (pid: 443) succeeded.
2024-06-19T08:39:17.415735+0200 tarragon manager[402]: [CRIT] manager         int boot(const boost::program_options::variables_map&) :: Exiting manager.
2024-06-19T08:39:17.450976+0200 tarragon systemd[1]: everest.service: Main process exited, code=exited, status=1/FAILURE
2024-06-19T08:39:17.452098+0200 tarragon systemd[1]: everest.service: Killing process 404 (controller) with signal SIGKILL.
2024-06-19T08:39:17.476945+0200 tarragon systemd[1]: everest.service: Failed with result 'exit-code'.

To Reproduce

  • connect EV (CP state B)
  • reboot charge controller
  • wait until EVerest comes up

Configuration:

active_modules:
  api_1:
    module: API
    connections:
      evse_manager:
        - module_id: connector_1
          implementation_id: evse
  api_2:
    module: API
    connections:
      evse_manager:
        - module_id: connector_2
          implementation_id: evse_manager
  tarragon_bsp:
    module: CbTarragonDriver
    config_module:
      contactor_1_feedback_type: nc
      relay_2_name: none
  tarragon_pluglock:
    module: CbTarragonPlugLock
  serialcommhub_x7:
    module: SerialCommHub
    config_implementation:
      main:
        baudrate: 115200
        serial_port: /dev/ttymxc0
        ignore_echo: true
  powermeter:
    module: PowermeterIskra_WM3M4C
    config_implementation:
      main:
        powermeter_device_id: 33
        model: Iskra_WM3M4_WM3M4C
        modbus_base_address: 30000
    connections:
      serial_comm_hub:
        - module_id: serialcommhub_x7
          implementation_id: main
  token_provider_1:
    config_implementation:
      main:
        timeout: 10
        token: deadbeef
        type: RFID
    connections:
      evse:
        - implementation_id: evse
          module_id: connector_1
    module: DummyTokenProvider
  token_provider_2:
    config_implementation:
      main:
        timeout: 10
        token: 2e7b711a
        type: RFID
    connections:
      evse:
        - implementation_id: evse_manager
          module_id: connector_2
    module: DummyTokenProvider
  connector_1:
    module: EvseManager
    config_module:
      connector_id: 1
      has_ventilation: false
      max_current_import_A: 16
      session_logging: true
    connections:
      bsp:
        - module_id: tarragon_bsp
          implementation_id: evse_board_support
      connector_lock:
        - module_id: tarragon_pluglock
          implementation_id: connector_lock
      powermeter_grid_side:
        - module_id: powermeter
          implementation_id: main
  connector_2:
    module: SatelliteController
    config_module:
      hostname: "192.168.1.11"
    connections:
      auth:
        - module_id: auth
          implementation_id: main
      system:
        - module_id: system_aggregator
          implementation_id: system
  system_aggregator:
    module: SystemAggregator
    connections:
      system:
        - module_id: system
          implementation_id: main
        - module_id: connector_2
          implementation_id: system
      satellite:
        - module_id: connector_2
          implementation_id: satellite
  energy_manager:
    module: EnergyManager
    connections:
      energy_trunk:
        - module_id: grid_connection_point
          implementation_id: energy_grid
  grid_connection_point:
    module: EnergyNode
    config_module:
      fuse_limit_A: 16
      phase_count: 3
    connections:
      energy_consumer:
        - module_id: connector_1
          implementation_id: energy_grid
        - module_id: connector_2
          implementation_id: energy
  auth:
    module: Auth
    config_module:
      connection_timeout: 10
      prioritize_authorization_over_stopping_transaction: true
      selection_algorithm: PlugEvents
    connections:
      token_provider:
        - module_id: token_provider_1
          implementation_id: main
        - module_id: token_provider_2
          implementation_id: main
        - module_id: ocpp
          implementation_id: auth_provider
      token_validator:
        - module_id: ocpp
          implementation_id: auth_validator
      evse_manager:
        - module_id: connector_1
          implementation_id: evse
        - module_id: connector_2
          implementation_id: evse_manager
  evse_security:
    module: EvseSecurity
  system:
    module: CbSystem
  ocpp:
    module: OCPP201
    config_module:
      CoreDatabasePath: /var/lib/everest/ocpp201
      DeviceModelDatabasePath: /var/lib/everest/ocpp201/device_model_storage.db
    connections:
      evse_manager:
        - module_id: connector_1
          implementation_id: evse
        - module_id: connector_2
          implementation_id: evse_manager
      auth:
        - module_id: auth
          implementation_id: main
      security:
        - module_id: evse_security
          implementation_id: main
      system:
        - module_id: system_aggregator
          implementation_id: system
  hmiled:
    module: GpioRgbLed
    config_module:
      led_red_gpio_line_name: DIGITAL_OUT_3
      led_green_gpio_line_name: DIGITAL_OUT_1
      led_blue_gpio_line_name: DIGITAL_OUT_2
    connections:
      auth:
        - module_id: auth
          implementation_id: main
      bsp:
        - module_id: tarragon_bsp
          implementation_id: evse_board_support
      evse:
        - module_id: connector_1
          implementation_id: evse
      system:
        - module_id: system_aggregator
          implementation_id: system

Anything else?

No response

@hikinggrass hikinggrass self-assigned this Jun 20, 2024
@hikinggrass
Copy link
Contributor

I'll have a look at this

@lategoodbye
Copy link
Author

@hikinggrass Did you found something?
In case not, how can I provide you a better log?

@hikinggrass
Copy link
Contributor

Do you have the ocpp message log? location printed in the line:
Logging OCPP messages to log file:
I suspect a broken ocpp message (which we should catch), but would be good to have this as a testcase

@hikinggrass
Copy link
Contributor

Another thing that might have happended is that the timestamp from the session_event that we parse from the evse_manager is somehow mangled. Can you add a log around these lines in the OCPP201 module so we might see if this timestamp is empty? https://github.com/EVerest/everest-core/blob/40f62a977bd54391d80b7c2774681df40fd59a79/modules/OCPP201/OCPP201.cpp#L640

@Pietfried
Copy link
Contributor

Might be mitigated with EVerest/everest-core#765 . Thanks for identifying the connection @lategoodbye !
Still this does not prevent having meter values with an empty string timestamp in all cases, so we still need to be able to handle this.

@barsnick barsnick changed the title DateTime parsing expection prevent initial EVerest start DateTime parsing exception prevents initial EVerest start Jul 18, 2024
@jannejy
Copy link
Contributor

jannejy commented Oct 8, 2024

It seems it can be closed as a dupliacte of #808 ?

@Pietfried
Copy link
Contributor

It seems it can be closed as a dupliacte of #808 ?

👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants