[PATCH 0/2] service: Improve Logging and Event Visibility at the Info Level

[PATCH 0/2] service: Improve Logging and Event Visibility at the Info Level

[Grant Erickson]

This improves service logging and event visibility at the info level
by making the following additions and changes:

  1. Make log output of online_check_is_enabled_check consistent,
     resulting in log entries similar to "Online check disabled;
     interface wlan0 [ wifi ] remains in ready state."

  2. Log service default, error, and state changes, resulting in log
     entries similar to:

       Interface eth0 [ ethernet ] is the default
       Interface wlan0 [ wifi ] error "online-check-failed"
       Interface wwan0 [ cellular ] state is online

Grant Erickson (2):
  service: Make log output of 'online_check_is_enabled_check'
    consistent.
  service: Log service default, error, and state changes.

 src/service.c | 69 +++++++++++++++++++++++++++++++++++++++++++++------
 1 file changed, 61 insertions(+), 8 deletions(-)

-- 
2.42.0

[PATCH 1/2] service: Make log output of 'online_check_is_enabled_check' consistent.

[Grant Erickson]

This makes the info-level log output of
'online_check_is_enabled_check' consistent with other messages using
the format of:

    ... [Ii]nterface <interface name> [ <service type> ] ...

to achieve:

    Online check disabled; interface wlan0 [ wifi ] remains in ready
    state.
---
 src/service.c | 12 ++++++++++--
 1 file changed, 10 insertions(+), 2 deletions(-)

diff --git a/src/service.c b/src/service.c
index 99b322a91684..d3bd1fe83b37 100644
--- a/src/service.c
+++ b/src/service.c
@@ -2195,9 +2195,17 @@ static void cancel_online_check(struct connman_service *service,
 static bool online_check_is_enabled_check(
 		const struct connman_service *service)
 {
+	g_autofree char *interface = NULL;
+
 	if (!__connman_service_is_online_check_enabled()) {
-		connman_info("Online check disabled. "
-			"Default service remains in READY state.");
+		interface = connman_service_get_interface(service);
+
+		connman_info("Online check disabled; "
+			"interface %s [ %s ] remains in %s state.",
+			interface,
+			__connman_service_type2string(service->type),
+			state2string(CONNMAN_SERVICE_STATE_READY));
+
 		return false;
 	}
 
-- 
2.42.0

[PATCH 2/2] service: Log service default, error, and state changes.

[Grant Erickson]

Service default, error, and state changes are significant enough and
low-frequency enough to warrant logging at the info level. This adds
log entries for each in the form:

    ... [Ii]nterface <interface name> [ <service type> ] ...

to achieve:

    Interface eth0 [ ethernet ] is the default
    Interface eth0 [ ethernet ] error "online-check-failed"
    Interface eth0 [ ethernet ] state is online

log entries for default, error, and state changes, respectively.
---
 src/service.c | 57 +++++++++++++++++++++++++++++++++++++++++++++------
 1 file changed, 51 insertions(+), 6 deletions(-)

diff --git a/src/service.c b/src/service.c
index d3bd1fe83b37..f3e022c91879 100644
--- a/src/service.c
+++ b/src/service.c
@@ -4187,6 +4187,17 @@ bool __connman_service_index_is_default(int index)
 	return __connman_service_get_index(service) == index;
 }
 
+static void service_log_default(const struct connman_service *service)
+{
+	g_autofree char *interface = NULL;
+
+	interface = connman_service_get_interface(service);
+
+	connman_info("Interface %s [ %s ] is the default",
+		interface,
+		__connman_service_type2string(service->type));
+}
+
 static void default_changed(const char *function)
 {
 	struct connman_service *service = connman_service_get_default();
@@ -4233,6 +4244,8 @@ static void default_changed(const char *function)
 	current_default = service;
 
 	if (service) {
+		service_log_default(service);
+
 		if (service->hostname &&
 				connman_setting_get_bool("AllowHostnameUpdates"))
 			__connman_utsname_set_hostname(service->hostname);
@@ -4257,10 +4270,24 @@ static void default_changed(const char *function)
 	__connman_notifier_default_changed(service);
 }
 
+static void service_log_state(const struct connman_service *service)
+{
+	g_autofree char *interface = NULL;
+
+	interface = connman_service_get_interface(service);
+
+	connman_info("Interface %s [ %s ] state is %s",
+		interface,
+		__connman_service_type2string(service->type),
+		state2string(service->state));
+}
+
 static void state_changed(struct connman_service *service)
 {
 	const char *str;
 
+	service_log_state(service);
+
 	__connman_notifier_service_state_changed(service, service->state);
 
 	str = state2string(service->state);
@@ -6450,6 +6477,19 @@ static DBusMessage *set_property(DBusConnection *conn,
 	return g_dbus_create_reply(msg, DBUS_TYPE_INVALID);
 }
 
+static void service_log_error(const struct connman_service *service,
+					enum connman_service_error error)
+{
+	g_autofree char *interface = NULL;
+
+	interface = connman_service_get_interface(service);
+
+	connman_warn("Interface %s [ %s ] error \"%s\"",
+		interface,
+		__connman_service_type2string(service->type),
+		error2string(error));
+}
+
 /**
  *  @brief
  *    Set the specified network service "Error" property.
@@ -6471,7 +6511,14 @@ static DBusMessage *set_property(DBusConnection *conn,
 static void set_error(struct connman_service *service,
 					enum connman_service_error error)
 {
-	const char *str;
+	const char *str = error2string(error);
+
+	if (!str)
+		str = "";
+
+	DBG("service %p (%s) error %d (%s)",
+		service, connman_service_get_identifier(service),
+		error, str);
 
 	if (service->error == error)
 		return;
@@ -6481,14 +6528,12 @@ static void set_error(struct connman_service *service,
 	if (!service->path)
 		return;
 
+	if (error != CONNMAN_SERVICE_ERROR_UNKNOWN)
+		service_log_error(service, error);
+
 	if (!allow_property_changed(service))
 		return;
 
-	str = error2string(service->error);
-
-	if (!str)
-		str = "";
-
 	connman_dbus_property_changed_basic(service->path,
 				CONNMAN_SERVICE_INTERFACE, "Error",
 				DBUS_TYPE_STRING, &str);
-- 
2.42.0

Re: [PATCH 1/2] service: Make log output of 'online_check_is_enabled_check' consistent.

[Denis Kenzior]

Hi Grant,

> @@ -2195,9 +2195,17 @@ static void cancel_online_check(struct connman_service *service,
>   static bool online_check_is_enabled_check(
>   		const struct connman_service *service)
>   {
> +	g_autofree char *interface = NULL;
> +
>   	if (!__connman_service_is_online_check_enabled()) {
> -		connman_info("Online check disabled. "
> -			"Default service remains in READY state.");
> +		interface = connman_service_get_interface(service);
> +
> +		connman_info("Online check disabled; "
> +			"interface %s [ %s ] remains in %s state.",
> +			interface,
> +			__connman_service_type2string(service->type),
> +			state2string(CONNMAN_SERVICE_STATE_READY));
> +

Does it make sense to add a specific method for such informational prints that 
will enforce the desired formatting pattern instead of relying on human 
intervention?

Regards,
-Denis

Re: [PATCH 1/2] service: Make log output of 'online_check_is_enabled_check' consistent.

[Grant Erickson]

On Dec 22, 2023, at 10:23 AM, Denis Kenzior <denkenz@gmail.com> wrote:
>> @@ -2195,9 +2195,17 @@ static void cancel_online_check(struct connman_service *service,
>>  static bool online_check_is_enabled_check(
>>  		const struct connman_service *service)
>>  {
>> +	g_autofree char *interface = NULL;
>> +
>>  	if (!__connman_service_is_online_check_enabled()) {
>> -		connman_info("Online check disabled. "
>> -			"Default service remains in READY state.");
>> +		interface = connman_service_get_interface(service);
>> +
>> +		connman_info("Online check disabled; "
>> +			"interface %s [ %s ] remains in %s state.",
>> +			interface,
>> +			__connman_service_type2string(service->type),
>> +			state2string(CONNMAN_SERVICE_STATE_READY));
>> +
> 
> Does it make sense to add a specific method for such informational prints that will enforce the desired formatting pattern instead of relying on human intervention?

Denis,

It’s a great point and one I’d considered. The scope of my changes seemed to small / narrow at that / this juncture. As we review logging across modules and the project at large and there’s an emergent pattern, I’m all for such a function / method.

Best,

Grant

-- 
Principal
Nuovations

gerickson@nuovations.com
http://www.nuovations.com/

Re: [PATCH 0/2] service: Improve Logging and Event Visibility at the Info Level

[Marcel Holtmann]

Hi Grant,

> This improves service logging and event visibility at the info level
> by making the following additions and changes:
> 
>  1. Make log output of online_check_is_enabled_check consistent,
>     resulting in log entries similar to "Online check disabled;
>     interface wlan0 [ wifi ] remains in ready state."
> 
>  2. Log service default, error, and state changes, resulting in log
>     entries similar to:
> 
>       Interface eth0 [ ethernet ] is the default
>       Interface wlan0 [ wifi ] error "online-check-failed"
>       Interface wwan0 [ cellular ] state is online
> 
> Grant Erickson (2):
>  service: Make log output of 'online_check_is_enabled_check'
>    consistent.
>  service: Log service default, error, and state changes.
> 
> src/service.c | 69 +++++++++++++++++++++++++++++++++++++++++++++------
> 1 file changed, 61 insertions(+), 8 deletions(-)

both patches have been applied.

Regards

Marcel

[PATCH 0/2] service: Improve Logging and Event Visibility at the Info Level

[Grant Erickson]

This improves service logging and event visibility at the info level
by making the following additions and changes:

  1. Make log output of online_check_is_enabled_check consistent,
     resulting in log entries similar to "Online check disabled;
     interface wlan0 [ wifi ] remains in ready state."

  2. Log service default, error, and state changes, resulting in log
     entries similar to:

       Interface eth0 [ ethernet ] is the default
       Interface wlan0 [ wifi ] error "online-check-failed"
       Interface wwan0 [ cellular ] state is online

Grant Erickson (2):
  service: Make log output of 'online_check_is_enabled_check'
    consistent.
  service: Log service default, error, and state changes.

 src/service.c | 69 +++++++++++++++++++++++++++++++++++++++++++++------
 1 file changed, 61 insertions(+), 8 deletions(-)

-- 
2.42.0