Make logging of WD and MON service correct

MON and WD services are using fsm.h, which calls log function. Such
messages were incorrectly logged as SERV (or random service) which made
debugging hard.

Solution is to add callback parameter to fsm functions and do actual
logging there.

Handling of failure states is also done in calback now.

Signed-off-by: Jan Friesse <jfriesse@redhat.com>
Reviewed-by: Fabio M. Di Nitto <fdinitto@redhat.com>
(cherry picked from commit 397cc89f01033c5c9ced26869c6f105044caee73)

exec/fsm.h

@@ -43,7 +43,18 @@ struct cs_fsm_entry;
 typedef void (*cs_fsm_event_action_fn)(struct cs_fsm* fsm, int32_t event, void * data);
 typedef const char * (*cs_fsm_state_to_str_fn)(struct cs_fsm* fsm, int32_t state);
 typedef const char * (*cs_fsm_event_to_str_fn)(struct cs_fsm* fsm, int32_t event);
+
+typedef void (*cs_fsm_cb)(struct cs_fsm *fsm, int cb_event, int32_t curr_state,
+    int32_t next_state, int32_t fsm_event, void *data);
+
 #define CS_FSM_NEXT_STATE_SIZE 32
+
+#define CS_FSM_STATE_NONE		-1
+
+#define CS_FSM_CB_EVENT_PROCESS_NF	0
+#define CS_FSM_CB_EVENT_STATE_SET	1
+#define CS_FSM_CB_EVENT_STATE_SET_NF	2
+
 struct cs_fsm_entry {
 	int32_t curr_state;
 	int32_t event;
@@ -66,7 +77,7 @@ struct cs_fsm {
  * so cs_fsm_process() sets the entry and cs_fsm_state_set()
  * sets the new state.
  */
-static inline void cs_fsm_process (struct cs_fsm *fsm, int32_t new_event, void * data)
+static inline void cs_fsm_process (struct cs_fsm *fsm, int32_t new_event, void * data, cs_fsm_cb cb)
 {
 	int32_t i;
 
@@ -81,12 +92,13 @@ static inline void cs_fsm_process (struct cs_fsm *fsm, int32_t new_event, void *
 			return;
 		}
 	}
-	log_printf (LOGSYS_LEVEL_ERROR, "Fsm:%s could not find event \"%s\" in state \"%s\"",
-		fsm->name, fsm->event_to_str(fsm, new_event), fsm->state_to_str(fsm, fsm->curr_state));
-	corosync_exit_error(COROSYNC_DONE_FATAL_ERR);
+
+	if (cb != NULL) {
+		cb(fsm, CS_FSM_CB_EVENT_PROCESS_NF, fsm->curr_state, CS_FSM_STATE_NONE, new_event, data);
+	}
 }
 
-static inline void cs_fsm_state_set (struct cs_fsm* fsm, int32_t next_state, void* data)
+static inline void cs_fsm_state_set (struct cs_fsm* fsm, int32_t next_state, void* data, cs_fsm_cb cb)
 {
 	int i;
 	struct cs_fsm_entry *entry = &fsm->table[fsm->curr_entry];
@@ -102,21 +114,16 @@ static inline void cs_fsm_state_set (struct cs_fsm* fsm, int32_t next_state, voi
 			break;
 		}
 		if (entry->next_states[i] == next_state) {
-			log_printf (LOGSYS_LEVEL_INFO, "Fsm:%s event \"%s\", state \"%s\" --> \"%s\"",
-				fsm->name,
-				fsm->event_to_str(fsm, entry->event),
-				fsm->state_to_str(fsm, fsm->table[fsm->curr_entry].curr_state),
-				fsm->state_to_str(fsm, next_state));
+			if (cb != NULL) {
+				cb(fsm, CS_FSM_CB_EVENT_STATE_SET, fsm->curr_state, next_state, entry->event, data);
+			}
 			fsm->curr_state = next_state;
 			return;
 		}
 	}
-	log_printf (LOGSYS_LEVEL_CRIT, "Fsm:%s Can't change state from \"%s\" to \"%s\" (event was \"%s\")",
-		fsm->name,
-		fsm->state_to_str(fsm, fsm->table[fsm->curr_entry].curr_state),
-		fsm->state_to_str(fsm, next_state),
-		fsm->event_to_str(fsm, entry->event));
-	corosync_exit_error(COROSYNC_DONE_FATAL_ERR);
+	if (cb != NULL) {
+		cb(fsm, CS_FSM_CB_EVENT_STATE_SET_NF, fsm->curr_state, next_state, entry->event, data);
+	}
 }
 
 #endif /* FSM_H_DEFINED */

exec/mon.c

@@ -45,7 +45,7 @@
 #include <corosync/list.h>
 #include <corosync/logsys.h>
 #include <corosync/icmap.h>
-#include "../exec/fsm.h"
+#include "fsm.h"
 
 #include "service.h"
 
@@ -184,6 +184,37 @@ static const char * mon_res_event_to_str(struct cs_fsm* fsm,
 	return NULL;
 }
 
+static void mon_fsm_cb (struct cs_fsm *fsm, int cb_event, int32_t curr_state,
+	int32_t next_state, int32_t fsm_event, void *data)
+{
+	switch (cb_event) {
+	case CS_FSM_CB_EVENT_PROCESS_NF:
+		log_printf (LOGSYS_LEVEL_ERROR, "Fsm:%s could not find event \"%s\" in state \"%s\"",
+			fsm->name, fsm->event_to_str(fsm, fsm_event), fsm->state_to_str(fsm, curr_state));
+		corosync_exit_error(COROSYNC_DONE_FATAL_ERR);
+		break;
+	case CS_FSM_CB_EVENT_STATE_SET:
+		log_printf (LOGSYS_LEVEL_INFO, "Fsm:%s event \"%s\", state \"%s\" --> \"%s\"",
+			fsm->name,
+			fsm->event_to_str(fsm, fsm_event),
+			fsm->state_to_str(fsm, fsm->table[fsm->curr_entry].curr_state),
+			fsm->state_to_str(fsm, next_state));
+		break;
+	case CS_FSM_CB_EVENT_STATE_SET_NF:
+		log_printf (LOGSYS_LEVEL_CRIT, "Fsm:%s Can't change state from \"%s\" to \"%s\" (event was \"%s\")",
+			fsm->name,
+			fsm->state_to_str(fsm, fsm->table[fsm->curr_entry].curr_state),
+			fsm->state_to_str(fsm, next_state),
+			fsm->event_to_str(fsm, fsm_event));
+	        corosync_exit_error(COROSYNC_DONE_FATAL_ERR);
+		break;
+	default:
+		log_printf (LOGSYS_LEVEL_CRIT, "Fsm: Can't find callback event!");
+	        corosync_exit_error(COROSYNC_DONE_FATAL_ERR);
+		break;
+	}
+}
+
 static void mon_fsm_state_set (struct cs_fsm* fsm,
 	enum mon_resource_state next_state, struct resource_instance* inst)
 {
@@ -193,7 +224,7 @@ static void mon_fsm_state_set (struct cs_fsm* fsm,
 
 	ENTER();
 
-	cs_fsm_state_set(fsm, next_state, inst);
+	cs_fsm_state_set(fsm, next_state, inst, mon_fsm_cb);
 
 	if (prev_state == fsm->curr_state) {
 		return;
@@ -328,7 +359,6 @@ static int32_t percent_mem_used_get(void)
 #endif /* HAVE_LIBSTATGRAB */
 }
 
-
 static void mem_update_stats_fn (void *data)
 {
 	struct resource_instance * inst = (struct resource_instance *)data;
@@ -347,7 +377,7 @@ static void mem_update_stats_fn (void *data)
 		icmap_set_uint64(key_name, timestamp);
 
 		if (new_value > inst->max.int32 && inst->fsm.curr_state != MON_S_FAILED) {
-			cs_fsm_process (&inst->fsm, MON_E_FAILURE, inst);
+			cs_fsm_process (&inst->fsm, MON_E_FAILURE, inst, mon_fsm_cb);
 		}
 	}
 	api->timer_add_duration(inst->period * MILLI_2_NANO_SECONDS,
@@ -395,7 +425,7 @@ static void load_update_stats_fn (void *data)
 		icmap_set_uint64(key_name, timestamp);
 
 		if (min15 > inst->max.dbl && inst->fsm.curr_state != MON_S_FAILED) {
-			cs_fsm_process (&inst->fsm, MON_E_FAILURE, &inst);
+			cs_fsm_process (&inst->fsm, MON_E_FAILURE, &inst, mon_fsm_cb);
 		}
 	}
 
@@ -418,7 +448,7 @@ static void mon_key_changed_cb (
 			"resource \"%s\" deleted from cmap!",
 			inst->name);
 
-		cs_fsm_process (&inst->fsm, MON_E_CONFIG_CHANGED, inst);
+		cs_fsm_process (&inst->fsm, MON_E_CONFIG_CHANGED, inst, mon_fsm_cb);
 	}
 
 	if (event == ICMAP_TRACK_MODIFY) {
@@ -430,7 +460,7 @@ static void mon_key_changed_cb (
 		if (strcmp(last_key_part, "max") == 0 ||
 		    strcmp(last_key_part, "poll_period") == 0) {
 			ENTER();
-			cs_fsm_process (&inst->fsm, MON_E_CONFIG_CHANGED, inst);
+			cs_fsm_process (&inst->fsm, MON_E_CONFIG_CHANGED, inst, mon_fsm_cb);
 		}
 	}
 }
@@ -475,7 +505,7 @@ static void mon_instance_init (struct resource_instance* inst)
 				tmp_value, inst->name);
 		}
 	}
-	cs_fsm_process (&inst->fsm, MON_E_CONFIG_CHANGED, inst);
+	cs_fsm_process (&inst->fsm, MON_E_CONFIG_CHANGED, inst, mon_fsm_cb);
 
 	icmap_track_add(inst->icmap_path,
 			ICMAP_TRACK_ADD | ICMAP_TRACK_MODIFY | ICMAP_TRACK_DELETE | ICMAP_TRACK_PREFIX,

exec/wd.c

@@ -47,7 +47,7 @@
 #include <corosync/list.h>
 #include <corosync/logsys.h>
 #include <corosync/icmap.h>
-#include "../exec/fsm.h"
+#include "fsm.h"
 
 #include "service.h"
 
@@ -178,6 +178,37 @@ static const char * wd_res_event_to_str(struct cs_fsm* fsm,
 	return NULL;
 }
 
+static void wd_fsm_cb (struct cs_fsm *fsm, int cb_event, int32_t curr_state,
+	int32_t next_state, int32_t fsm_event, void *data)
+{
+	switch (cb_event) {
+	case CS_FSM_CB_EVENT_PROCESS_NF:
+		log_printf (LOGSYS_LEVEL_ERROR, "Fsm:%s could not find event \"%s\" in state \"%s\"",
+			fsm->name, fsm->event_to_str(fsm, fsm_event), fsm->state_to_str(fsm, curr_state));
+		corosync_exit_error(COROSYNC_DONE_FATAL_ERR);
+		break;
+	case CS_FSM_CB_EVENT_STATE_SET:
+		log_printf (LOGSYS_LEVEL_INFO, "Fsm:%s event \"%s\", state \"%s\" --> \"%s\"",
+			fsm->name,
+			fsm->event_to_str(fsm, fsm_event),
+			fsm->state_to_str(fsm, fsm->table[fsm->curr_entry].curr_state),
+			fsm->state_to_str(fsm, next_state));
+		break;
+	case CS_FSM_CB_EVENT_STATE_SET_NF:
+		log_printf (LOGSYS_LEVEL_CRIT, "Fsm:%s Can't change state from \"%s\" to \"%s\" (event was \"%s\")",
+			fsm->name,
+			fsm->state_to_str(fsm, fsm->table[fsm->curr_entry].curr_state),
+			fsm->state_to_str(fsm, next_state),
+			fsm->event_to_str(fsm, fsm_event));
+	        corosync_exit_error(COROSYNC_DONE_FATAL_ERR);
+		break;
+	default:
+		log_printf (LOGSYS_LEVEL_CRIT, "Fsm: Unknown callback event!");
+	        corosync_exit_error(COROSYNC_DONE_FATAL_ERR);
+		break;
+	}
+}
+
 /*
  * returns (CS_TRUE == OK, CS_FALSE == failed)
  */
@@ -273,7 +304,7 @@ static void wd_config_changed (struct cs_fsm* fsm, int32_t event, void * data)
 		 */
 		log_printf (LOGSYS_LEVEL_WARNING,
 			"resource %s missing a recovery key.", ref->name);
-		cs_fsm_state_set(&ref->fsm, WD_S_STOPPED, ref);
+		cs_fsm_state_set(&ref->fsm, WD_S_STOPPED, ref, wd_fsm_cb);
 		return;
 	}
 	snprintf(key_name, ICMAP_KEYNAME_MAXLEN, "%s%s", ref->res_path, "state");
@@ -282,7 +313,7 @@ static void wd_config_changed (struct cs_fsm* fsm, int32_t event, void * data)
 		*/
 		log_printf (LOGSYS_LEVEL_WARNING,
 			"resource %s missing a state key.", ref->name);
-		cs_fsm_state_set(&ref->fsm, WD_S_STOPPED, ref);
+		cs_fsm_state_set(&ref->fsm, WD_S_STOPPED, ref, wd_fsm_cb);
 		return;
 	}
 	if (ref->check_timer) {
@@ -291,11 +322,11 @@ static void wd_config_changed (struct cs_fsm* fsm, int32_t event, void * data)
 	}
 
 	if (strcmp(wd_stopped_str, state) == 0) {
-		cs_fsm_state_set(&ref->fsm, WD_S_STOPPED, ref);
+		cs_fsm_state_set(&ref->fsm, WD_S_STOPPED, ref, wd_fsm_cb);
 	} else {
 		api->timer_add_duration(next_timeout * MILLI_2_NANO_SECONDS,
 			ref, wd_resource_check_fn, &ref->check_timer);
-		cs_fsm_state_set(&ref->fsm, WD_S_RUNNING, ref);
+		cs_fsm_state_set(&ref->fsm, WD_S_RUNNING, ref, wd_fsm_cb);
 	}
 	free(state);
 }
@@ -321,7 +352,7 @@ static void wd_resource_failed (struct cs_fsm* fsm, int32_t event, void * data)
 	else if (strcmp (ref->recovery, "shutdown") == 0) {
 		reboot(RB_POWER_OFF);
 	}
-	cs_fsm_state_set(fsm, WD_S_FAILED, data);
+	cs_fsm_state_set(fsm, WD_S_FAILED, data, wd_fsm_cb);
 }
 
 static void wd_key_changed(
@@ -350,7 +381,7 @@ static void wd_key_changed(
 			return;
 		}
 
-		cs_fsm_process(&ref->fsm, WD_E_CONFIG_CHANGED, ref);
+		cs_fsm_process(&ref->fsm, WD_E_CONFIG_CHANGED, ref, wd_fsm_cb);
 	}
 
 	if (event == ICMAP_TRACK_DELETE && ref != NULL) {
@@ -375,7 +406,7 @@ static void wd_resource_check_fn (void* resource_ref)
 	struct resource* ref = (struct resource*)resource_ref;
 
 	if (wd_resource_state_is_ok (ref) == CS_FALSE) {
-		cs_fsm_process(&ref->fsm, WD_E_FAILURE, ref);
+		cs_fsm_process(&ref->fsm, WD_E_FAILURE, ref, wd_fsm_cb);
 		return;
 	}
 	api->timer_add_duration(ref->check_timeout*MILLI_2_NANO_SECONDS,
@@ -458,7 +489,7 @@ static int32_t wd_resource_create (char *res_path, char *res_name)
 		ref,
 		wd_resource_check_fn, &ref->check_timer);
 
-	cs_fsm_state_set(&ref->fsm, WD_S_RUNNING, ref);
+	cs_fsm_state_set(&ref->fsm, WD_S_RUNNING, ref, wd_fsm_cb);
 	return 0;
 }