Improved logging around websocket connection

config/v16/profile_schemas/Security.json

@@ -14,7 +14,7 @@
         "AuthorizationKey": {
             "type": "string",
             "description": "The basic authentication password is used for HTTP Basic Authentication",
-            "minLength": 16,
+            "minLength": 8,
             "readOnly": false
         },
         "CertificateSignedMaxChainSize": {

include/ocpp/common/websocket/websocket_base.hpp

@@ -59,6 +59,9 @@ class WebsocketBase {
     /// \brief getter for authorization header for connection with basic authentication
     std::optional<std::string> getAuthorizationHeader();
 
+    /// \brief Logs websocket connection error
+    void log_on_fail(const std::error_code& ec, const boost::system::error_code& transport_ec, const int http_status);
+
     /// \brief send a websocket ping
     virtual void ping() = 0;
 

include/ocpp/v16/types.hpp

@@ -143,11 +143,11 @@ std::ostream& operator<<(std::ostream& os, const SupportedFeatureProfiles& suppo
 
 /// \brief Contains the different connection states of the charge point
 enum ChargePointConnectionState {
-    Disconnected,
-    Connected,
-    Booted,
-    Pending,
-    Rejected,
+    Disconnected, // state when disconnected
+    Connected, // state when ws is connected
+    Booted, // state when ws is connected and BootNotifcation had been Accepted
+    Pending, // state when ws is connected and state when BootNotifcation is Pending
+    Rejected, // state when ws is connected and state when BootNotifcation had been Rejected
 };
 namespace conversions {
 /// \brief Converts the given ChargePointConnectionState \p e to std::string

lib/ocpp/common/websocket/websocket_base.cpp

@@ -17,6 +17,11 @@ WebsocketBase::WebsocketBase(const WebsocketConnectionOptions& connection_option
     message_callback(nullptr),
     reconnect_timer(nullptr) {
     this->ping_timer = std::make_unique<Everest::SteadyTimer>();
+    const auto auth_key = connection_options.authorization_key;
+    if (auth_key.has_value() and auth_key.value().length() < 16) {
+        EVLOG_warning << "AuthorizationKey with only " << auth_key.value().length()
+                      << " characters has been configured";
+    }
 }
 
 WebsocketBase::~WebsocketBase() {
@@ -76,17 +81,25 @@ bool WebsocketBase::is_connected() {
 std::optional<std::string> WebsocketBase::getAuthorizationHeader() {
     std::optional<std::string> auth_header = std::nullopt;
     const auto authorization_key = this->connection_options.authorization_key;
-    if (authorization_key) {
+    if (authorization_key.has_value()) {
         EVLOG_debug << "AuthorizationKey present, encoding authentication header";
         std::string plain_auth_header = this->connection_options.chargepoint_id + ":" + authorization_key.value();
         auth_header.emplace(std::string("Basic ") + websocketpp::base64_encode(plain_auth_header));
-
-        EVLOG_info << "Basic Auth header: " << auth_header.value();
+        EVLOG_debug << "Basic Auth header: " << auth_header.value();
     }
 
     return auth_header;
 }
 
+void WebsocketBase::log_on_fail(const std::error_code& ec, const boost::system::error_code& transport_ec,
+                                const int http_status) {
+    EVLOG_error << "Failed to connect to websocket server"
+                << ", error_code: " << ec.value() << ", reason: " << ec.message()
+                << ", HTTP response code: " << http_status << ", category: " << ec.category().name()
+                << ", transport error code: " << transport_ec.value()
+                << ", Transport error category: " << transport_ec.category().name();
+}
+
 void WebsocketBase::set_websocket_ping_interval(int32_t interval_s) {
     if (this->ping_timer) {
         this->ping_timer->stop();

lib/ocpp/common/websocket/websocket_plain.cpp

@@ -165,7 +165,7 @@ void WebsocketPlain::connect_plain(int32_t security_profile, bool try_once) {
 
 void WebsocketPlain::on_open_plain(client* c, websocketpp::connection_hdl hdl, int32_t security_profile) {
     (void)c; // client is not used in this function
-    EVLOG_info << "Connected to plain websocket successfully. Executing connected callback";
+    EVLOG_info << "OCPP client successfully connected to plain websocket server";
     this->m_is_connected = true;
     this->connection_options.security_profile = security_profile;
     this->set_websocket_ping_interval(this->connection_options.ping_interval_s);
@@ -201,17 +201,12 @@ void WebsocketPlain::on_close_plain(client* c, websocketpp::connection_hdl hdl)
 
 void WebsocketPlain::on_fail_plain(client* c, websocketpp::connection_hdl hdl, bool try_once) {
     client::connection_ptr con = c->get_con_from_hdl(hdl);
-    auto error_code = con->get_ec();
-    EVLOG_error << "Failed to connect to plain websocket server " << con->get_response_header("Server")
-                << ", code: " << error_code.value() << ", reason: " << error_code.message()
-                << ", response code: " << con->get_response_code();
-    EVLOG_error << "Failed to connect to plain websocket server "
-                << ", code: " << con->get_transport_ec().value() << ", reason: " << con->get_transport_ec().message()
-                << ", category: " << con->get_transport_ec().category().name();
-    EVLOG_error << "Close code: " << con->get_local_close_code() << ", close reason: " << con->get_local_close_reason();
+    const auto ec = con->get_ec();
+    this->log_on_fail(ec, con->get_transport_ec(), con->get_response_code());
+
     // when connecting with new security profile websocket should only try to connect once
     if (!try_once) {
-        this->reconnect(error_code, this->reconnect_interval_ms);
+        this->reconnect(ec, this->reconnect_interval_ms);
     } else {
         this->disconnected_callback();
     }

lib/ocpp/common/websocket/websocket_tls.cpp

@@ -254,7 +254,7 @@ void WebsocketTLS::connect_tls(int32_t security_profile, bool try_once) {
 }
 void WebsocketTLS::on_open_tls(tls_client* c, websocketpp::connection_hdl hdl, int32_t security_profile) {
     (void)c; // tlc_client is not used in this function
-    EVLOG_info << "Connected to TLS websocket successfully";
+    EVLOG_info << "OCPP client successfully connected to TLS websocket server";
     this->m_is_connected = true;
     this->connection_options.security_profile = security_profile;
     this->set_websocket_ping_interval(this->connection_options.ping_interval_s);
@@ -289,15 +289,8 @@ void WebsocketTLS::on_close_tls(tls_client* c, websocketpp::connection_hdl hdl)
 }
 void WebsocketTLS::on_fail_tls(tls_client* c, websocketpp::connection_hdl hdl, bool try_once) {
     tls_client::connection_ptr con = c->get_con_from_hdl(hdl);
-    auto error_code = con->get_ec();
-    auto transport_ec = con->get_transport_ec();
-    EVLOG_error << "Failed to connect to TLS websocket server " << con->get_response_header("Server")
-                << ", code: " << error_code.value() << ", reason: " << error_code.message()
-                << ", response code: " << con->get_response_code();
-    EVLOG_error << "Failed to connect to TLS websocket server "
-                << ", code: " << transport_ec.value() << ", reason: " << transport_ec.message()
-                << ", category: " << transport_ec.category().name();
-    EVLOG_error << "Close code: " << con->get_local_close_code() << ", close reason: " << con->get_local_close_reason();
+    const auto ec = con->get_ec();
+    this->log_on_fail(ec, con->get_transport_ec(), con->get_response_code());
 
     // TODO(piet): Trigger SecurityEvent in case InvalidCentralSystemCertificate
 
@@ -308,7 +301,7 @@ void WebsocketTLS::on_fail_tls(tls_client* c, websocketpp::connection_hdl hdl, b
     }
 
     if (!try_once) {
-        this->reconnect(error_code, this->reconnect_interval_ms);
+        this->reconnect(ec, this->reconnect_interval_ms);
     } else {
         this->disconnected_callback();
     }

lib/ocpp/v16/charge_point_configuration.cpp

@@ -2175,11 +2175,11 @@ ConfigurationStatus ChargePointConfiguration::set(CiString<50> key, CiString<500
     }
     if (key == "AuthorizationKey") {
         std::string authorization_key = value.get();
-        if (authorization_key.length() >= 16) {
+        if (authorization_key.length() >= 8) {
             this->setAuthorizationKey(value.get());
             return ConfigurationStatus::Accepted;
         } else {
-            EVLOG_debug << "AuthorizationKey is < 16 bytes";
+            EVLOG_warning << "Attempt to change AuthorizationKey to value with < 8 characters";
             return ConfigurationStatus::Rejected;
         }
     }

lib/ocpp/v16/charge_point_impl.cpp

@@ -777,6 +777,10 @@ void ChargePointImpl::connected_callback() {
         }
         break;
     }
+    case ChargePointConnectionState::Pending: {
+        // in Pending state this can happen when we reconnected while the BootNotification had not been yet accepted
+        break;
+    }
     default:
         EVLOG_error << "Connected but not in state 'Disconnected' or 'Booted', something is wrong: "
                     << this->connection_state;
@@ -1023,16 +1027,15 @@ void ChargePointImpl::handleBootNotificationResponse(ocpp::CallResult<BootNotifi
     }
     case RegistrationStatus::Pending:
         this->connection_state = ChargePointConnectionState::Pending;
-
-        EVLOG_debug << "BootNotification response is pending.";
+        EVLOG_info << "BootNotification response is pending.";
         this->boot_notification_timer->timeout(std::chrono::seconds(call_result.msg.interval));
         break;
     default:
         this->connection_state = ChargePointConnectionState::Rejected;
         // In this state we are not allowed to send any messages to the central system, even when
         // requested. The first time we are allowed to send a message (a BootNotification) is
         // after boot_time + heartbeat_interval if the msg.interval is 0, or after boot_timer + msg.interval
-        EVLOG_debug << "BootNotification was rejected, trying again in " << this->configuration->getHeartbeatInterval()
+        EVLOG_info << "BootNotification was rejected, trying again in " << this->configuration->getHeartbeatInterval()
                     << "s";
 
         this->boot_notification_timer->timeout(std::chrono::seconds(call_result.msg.interval));
@@ -1128,19 +1131,19 @@ void ChargePointImpl::handleChangeConfigurationRequest(ocpp::Call<ChangeConfigur
                 } else if (call.msg.key == "ClockAlignedDataInterval") {
                     this->update_clock_aligned_meter_values_interval();
                 } else if (call.msg.key == "AuthorizationKey") {
-                    /*SECURITYLOG*/ EVLOG_debug << "AuthorizationKey was changed by central system";
+                    EVLOG_info << "AuthorizationKey was changed by central system";
                     if (this->configuration->getSecurityProfile() == 0) {
-                        EVLOG_debug << "AuthorizationKey was changed while on security profile 0.";
+                        EVLOG_info << "AuthorizationKey was changed while on security profile 0.";
                     } else if (this->configuration->getSecurityProfile() == 1 ||
                                this->configuration->getSecurityProfile() == 2) {
-                        EVLOG_debug
+                        EVLOG_info
                             << "AuthorizationKey was changed while on security profile 1 or 2. Reconnect Websocket.";
                         ocpp::CallResult<ChangeConfigurationResponse> call_result(response, call.uniqueId);
                         this->send<ChangeConfigurationResponse>(call_result);
                         responded = true;
                         this->websocket->reconnect(std::error_code(), 1000);
                     } else {
-                        EVLOG_debug << "AuthorizationKey was changed while on security profile 3. Nothing to do.";
+                        EVLOG_info << "AuthorizationKey was changed while on security profile 3. Nothing to do.";
                     }
                 } else if (call.msg.key == "SecurityProfile") {
                     try {