[pve-devel] [PATCH cluster 0/3] logging improvements

[pve-devel] [PATCH cluster 0/3] logging improvements

[Fabian Grünbichler]

noticed while debugging the (as it turns out) missing lock issue that
qb_log is not thread-safe by default, this patch series switches to
threaded, non-blocking logging.

Fabian Grünbichler (3):
  pmxcfs: switch log domain to enum
  pmxcfs: set log domain in more places
  pmxcfs: enable QB log thread

 data/src/cfs-utils.h      | 36 ++++++++++++++++++++++++++++++++----
 data/src/dfsm.h           |  6 +++---
 data/src/loop.h           |  2 +-
 data/src/cfs-plug-func.c  |  2 ++
 data/src/cfs-plug-link.c  |  2 ++
 data/src/cfs-plug-memdb.c |  2 ++
 data/src/cfs-plug.c       |  2 ++
 data/src/cfs-utils.c      | 16 ++++++++--------
 data/src/confdb.c         |  3 ++-
 data/src/database.c       |  1 +
 data/src/dcdb.c           |  3 ++-
 data/src/dfsm.c           | 18 +++++++++++-------
 data/src/logger.c         |  2 ++
 data/src/loop.c           | 11 ++++++-----
 data/src/memdb.c          |  2 ++
 data/src/pmxcfs.c         | 21 ++++++++++++---------
 data/src/quorum.c         |  3 ++-
 data/src/server.c         |  1 +
 data/src/status.c         |  3 ++-
 19 files changed, 95 insertions(+), 41 deletions(-)

-- 
2.20.1

[pve-devel] [RFC cluster 1/3] pmxcfs: switch log domain to enum

[Fabian Grünbichler]

GQuarks does not work correctly across threads, which can cause
misattribution to log domains, e.g.

[status] notice: members: 1/2116, 2/2454111
[status] notice: starting data syncronisation
[status] notice: members: 1/2116, 2/2454111
[status] notice: starting data syncronisation
[dcdb] notice: received sync request (epoch 1/2116/00000036)
[status] notice: received sync request (epoch 1/2116/00000036)
[dcdb] notice: received all states
[dcdb] notice: leader is 1/2116
[dcdb] notice: synced members: 1/2116, 2/2454111
[dcdb] notice: all data is up to date
[status] notice: received all states
[status] notice: all data is up to date

gets logged instead of

[dcdb] notice: members: 1/2116, 2/2454111, 3/1254
[dcdb] notice: starting data syncronisation
[status] notice: members: 1/2116, 2/2454111, 3/1254
[status] notice: starting data syncronisation
[dcdb] notice: received sync request (epoch 1/2116/00000035)
[status] notice: received sync request (epoch 1/2116/00000035)
[dcdb] notice: received all states
[dcdb] notice: leader is 1/2116
[dcdb] notice: synced members: 1/2116, 2/2454111
[dcdb] notice: all data is up to date
[status] notice: received all states
[status] notice: all data is up to date

this only happens with threaded logging (not yet enabled).

Signed-off-by: Fabian Grünbichler <f.gruenbichler@proxmox.com>
---
not entirely happy with this approach - open for more elegant
suggestions ;)

 data/src/cfs-utils.h | 36 ++++++++++++++++++++++++++++++++----
 data/src/dfsm.h      |  6 +++---
 data/src/loop.h      |  2 +-
 data/src/cfs-utils.c |  4 ++--
 data/src/confdb.c    |  2 +-
 data/src/dcdb.c      |  2 +-
 data/src/dfsm.c      |  4 ++--
 data/src/loop.c      | 10 +++++-----
 data/src/pmxcfs.c    | 14 +++++---------
 data/src/quorum.c    |  2 +-
 data/src/status.c    |  2 +-
 11 files changed, 54 insertions(+), 30 deletions(-)

diff --git a/data/src/cfs-utils.h b/data/src/cfs-utils.h
index eb86379..51cfef0 100644
--- a/data/src/cfs-utils.h
+++ b/data/src/cfs-utils.h
@@ -37,6 +37,34 @@
 #define CFS_MAX(a, b)		(((a) > (b)) ? (a) : (b))
 #define CFS_MIN(a, b)		(((a) < (b)) ? (a) : (b))
 
+typedef enum {
+    CFS_LOG_MAIN = 0,
+    CFS_LOG_LOOP = 1,
+    CFS_LOG_IPCS = 2,
+    CFS_LOG_GLIB = 3,
+    CFS_LOG_CONFDB = 4,
+    CFS_LOG_QUORUM = 5,
+    CFS_LOG_DB = 6,
+    CFS_LOG_STATUS = 7,
+    CFS_LOG_DCDB = 8,
+    CFS_LOG_UNKNOWN = 9,
+    CFS_LOG_LAST_VALUE = 10,
+} cfs_log_domain_t;
+
+static const char * const cfs_log_domain_strings[] = {
+    "main",
+    "loop",
+    "ipcs",
+    "glib",
+    "confdb",
+    "quorum",
+    "database",
+    "status",
+    "dcdb",
+    "unknown",
+    "invalid",
+};
+
 typedef struct {
 	char *nodename;
 	char *ip;
@@ -55,7 +83,7 @@ utf8_to_ascii(
 
 void 
 cfs_log(
-	const gchar *log_domain,
+	cfs_log_domain_t log_domain,
 	GLogLevelFlags log_level,
 	const char *file,
 	int         line,
@@ -72,7 +100,7 @@ void ipc_log_fn(
 
 #define cfs_debug(...)  G_STMT_START { \
 	if (cfs.debug) \
-		cfs_log(G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__); \
+		cfs_log(CFS_LOG_UNKNOWN, G_LOG_LEVEL_DEBUG, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__); \
 	} G_STMT_END
 
 #define cfs_dom_debug(domain, ...)  G_STMT_START {	\
@@ -80,9 +108,9 @@ void ipc_log_fn(
 		cfs_log(domain, G_LOG_LEVEL_DEBUG, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__); \
 	} G_STMT_END
 
-#define cfs_critical(...)  cfs_log(G_LOG_DOMAIN, G_LOG_LEVEL_CRITICAL, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
+#define cfs_critical(...)  cfs_log(CFS_LOG_UNKNOWN, G_LOG_LEVEL_CRITICAL, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
 #define cfs_dom_critical(domain, ...)  cfs_log(domain, G_LOG_LEVEL_CRITICAL, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
-#define cfs_message(...)  cfs_log(G_LOG_DOMAIN, G_LOG_LEVEL_MESSAGE, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
+#define cfs_message(...)  cfs_log(CFS_LOG_UNKNOWN, G_LOG_LEVEL_MESSAGE, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
 #define cfs_dom_message(domain, ...)  cfs_log(domain, G_LOG_LEVEL_MESSAGE, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
 
 guint64 
diff --git a/data/src/dfsm.h b/data/src/dfsm.h
index 858127f..79d20a4 100644
--- a/data/src/dfsm.h
+++ b/data/src/dfsm.h
@@ -120,9 +120,9 @@ typedef struct {
 dfsm_t *
 dfsm_new(
 	gpointer data,
-	const char *group_name, 
-	const char *log_domain, 
-	guint32 protocol_version, 
+	const char *group_name,
+	cfs_log_domain_t log_domain,
+	guint32 protocol_version,
 	dfsm_callbacks_t *callbacks);
 
 void 
diff --git a/data/src/loop.h b/data/src/loop.h
index 68b783c..b1e39e2 100644
--- a/data/src/loop.h
+++ b/data/src/loop.h
@@ -58,7 +58,7 @@ typedef struct {
 
 cfs_service_t *cfs_service_new(
 	cfs_service_callbacks_t *callbacks,
-	const char *log_domain,
+	cfs_log_domain_t log_domain,
 	gpointer context);
 
 gpointer cfs_service_get_context(
diff --git a/data/src/cfs-utils.c b/data/src/cfs-utils.c
index 5770833..134c1cb 100644
--- a/data/src/cfs-utils.c
+++ b/data/src/cfs-utils.c
@@ -108,7 +108,7 @@ utf8_to_ascii(
 
 void 
 cfs_log(
-	const gchar *log_domain,
+	cfs_log_domain_t log_domain,
 	GLogLevelFlags log_level,
 	const char *file,
 	int         line,
@@ -152,7 +152,7 @@ cfs_log(
 	char msg[8192];
 	utf8_to_ascii(msg, sizeof(msg), orgmsg, FALSE);
 
-	uint32_t tag = g_quark_from_string(log_domain);
+	uint32_t tag = (uint32_t) log_domain;
 
 	qb_log_from_external_source(func, file, "%s", level, line, tag, msg);
 
diff --git a/data/src/confdb.c b/data/src/confdb.c
index 839f576..7c4c992 100644
--- a/data/src/confdb.c
+++ b/data/src/confdb.c
@@ -344,7 +344,7 @@ service_confdb_new(void)
 	if (!private)
 		return NULL;
 
-	service = cfs_service_new(&cfs_confdb_callbacks, G_LOG_DOMAIN, private);
+	service = cfs_service_new(&cfs_confdb_callbacks, CFS_LOG_CONFDB, private);
 
 	return service;
 }
diff --git a/data/src/dcdb.c b/data/src/dcdb.c
index b690355..b4f4359 100644
--- a/data/src/dcdb.c
+++ b/data/src/dcdb.c
@@ -949,6 +949,6 @@ dfsm_t *dcdb_new(memdb_t *memdb)
 {
 	g_return_val_if_fail(memdb != NULL, NULL);
  
-	return dfsm_new(memdb, DCDB_CPG_GROUP_NAME, G_LOG_DOMAIN, 
+	return dfsm_new(memdb, DCDB_CPG_GROUP_NAME, CFS_LOG_DCDB,
 			DCDB_PROTOCOL_VERSION, &dcdb_dfsm_callbacks);
 }
diff --git a/data/src/dfsm.c b/data/src/dfsm.c
index ddfcc23..ab761e1 100644
--- a/data/src/dfsm.c
+++ b/data/src/dfsm.c
@@ -103,7 +103,7 @@ typedef struct {
 } dfsm_queued_message_t;
 
 struct dfsm {
-	const char *log_domain;
+	cfs_log_domain_t log_domain;
 	cpg_callbacks_t *cpg_callbacks;
 	dfsm_callbacks_t *dfsm_callbacks;
 	cpg_handle_t cpg_handle;
@@ -1223,7 +1223,7 @@ dfsm_t *
 dfsm_new(
 	gpointer data, 
 	const char *group_name, 
-	const char *log_domain,
+	cfs_log_domain_t log_domain,
 	guint32 protocol_version, 
 	dfsm_callbacks_t *callbacks)
 {
diff --git a/data/src/loop.c b/data/src/loop.c
index a80fc66..09c8590 100644
--- a/data/src/loop.c
+++ b/data/src/loop.c
@@ -40,8 +40,8 @@
 #include "loop.h"
 
 struct cfs_service {
-	qb_loop_t *qbloop;	
-	const char *log_domain;
+	qb_loop_t *qbloop;
+	cfs_log_domain_t log_domain;
 	cfs_service_callbacks_t *callbacks;
 	gboolean restartable;
 	gpointer context;
@@ -98,7 +98,7 @@ cfs_service_set_restartable(
 cfs_service_t *
 cfs_service_new(
 	cfs_service_callbacks_t *callbacks,
-	const char *log_domain,
+	cfs_log_domain_t log_domain,
 	gpointer context)
 {
 	g_return_val_if_fail(callbacks != NULL, NULL);
@@ -113,7 +113,7 @@ cfs_service_new(
 	if (log_domain)
 		service->log_domain = log_domain;
 	else
-		service->log_domain = G_LOG_DOMAIN;
+		service->log_domain = CFS_LOG_LOOP;
 
 	service->callbacks = callbacks;
 
@@ -170,7 +170,7 @@ cfs_loop_add_service(
 {
 	g_return_val_if_fail(loop != NULL, FALSE);
 	g_return_val_if_fail(service != NULL, FALSE);
-	g_return_val_if_fail(service->log_domain != NULL, FALSE);
+	g_return_val_if_fail(service->log_domain < CFS_LOG_LAST_VALUE, FALSE);
 
 	service->priority = priority;
 	service->qbloop = loop->qbloop;
diff --git a/data/src/pmxcfs.c b/data/src/pmxcfs.c
index b6d6576..d5a3aac 100644
--- a/data/src/pmxcfs.c
+++ b/data/src/pmxcfs.c
@@ -81,7 +81,7 @@ static void glib_log_handler(const gchar *log_domain,
 			     gpointer user_data)
 {
 
-	cfs_log(log_domain, log_level, NULL, 0, NULL, "%s", message);
+	cfs_log(CFS_LOG_GLIB, log_level, NULL, 0, NULL, "%s - %s", log_domain, message);
 }
 
 static gboolean write_pidfile(pid_t pid)
@@ -760,15 +760,11 @@ static const char*
 log_tags_stringify(uint32_t tags) {
 	if (qb_bit_is_set(tags, QB_LOG_TAG_LIBQB_MSG_BIT)) {
 		return "libqb";
+	} else if (tags >= CFS_LOG_LAST_VALUE) {
+		return cfs_log_domain_strings[CFS_LOG_MAIN];
 	} else {
-		GQuark quark = tags;
-		const char *domain = g_quark_to_string(quark);
-		if (domain != NULL) {
-			return domain;
-		} else {
-			return "main";
-		}
- 	}
+		return cfs_log_domain_strings[tags];
+	}
 }
 
 int main(int argc, char *argv[])
diff --git a/data/src/quorum.c b/data/src/quorum.c
index 9df0e90..0a75f7f 100644
--- a/data/src/quorum.c
+++ b/data/src/quorum.c
@@ -202,7 +202,7 @@ cfs_service_t *service_quorum_new(void)
 	if (!private)
 		return NULL;
 
-	service = cfs_service_new(&cfs_quorum_callbacks, G_LOG_DOMAIN, private); 
+	service = cfs_service_new(&cfs_quorum_callbacks, CFS_LOG_QUORUM, private); 
 
 	return service;
 }
diff --git a/data/src/status.c b/data/src/status.c
index e15a257..004f02e 100644
--- a/data/src/status.c
+++ b/data/src/status.c
@@ -1834,7 +1834,7 @@ cfs_status_dfsm_new(void)
 {
 	g_mutex_lock (&mutex);
 
-	cfs_status.kvstore = dfsm_new(NULL, KVSTORE_CPG_GROUP_NAME, G_LOG_DOMAIN,
+	cfs_status.kvstore = dfsm_new(NULL, KVSTORE_CPG_GROUP_NAME, CFS_LOG_STATUS,
 				      0, &kvstore_dfsm_callbacks);
 	g_mutex_unlock (&mutex);
 
-- 
2.20.1

[pve-devel] [PATCH cluster 2/3] pmxcfs: set log domain in more places

[Fabian Grünbichler]

so that we can default to the set log domain instead of 'unknown' in
cfs_debug/message/critical. used log domain values are copied from old
G_LOG_DOMAIN behaviour.

Signed-off-by: Fabian Grünbichler <f.gruenbichler@proxmox.com>
---
 data/src/cfs-utils.h      |  6 +++---
 data/src/cfs-plug-func.c  |  2 ++
 data/src/cfs-plug-link.c  |  2 ++
 data/src/cfs-plug-memdb.c |  2 ++
 data/src/cfs-plug.c       |  2 ++
 data/src/cfs-utils.c      | 12 ++++++------
 data/src/confdb.c         |  1 +
 data/src/database.c       |  1 +
 data/src/dcdb.c           |  1 +
 data/src/dfsm.c           | 14 +++++++++-----
 data/src/logger.c         |  2 ++
 data/src/loop.c           |  1 +
 data/src/memdb.c          |  2 ++
 data/src/pmxcfs.c         |  2 ++
 data/src/quorum.c         |  1 +
 data/src/server.c         |  1 +
 data/src/status.c         |  1 +
 17 files changed, 39 insertions(+), 14 deletions(-)

diff --git a/data/src/cfs-utils.h b/data/src/cfs-utils.h
index 51cfef0..ac5f6eb 100644
--- a/data/src/cfs-utils.h
+++ b/data/src/cfs-utils.h
@@ -100,7 +100,7 @@ void ipc_log_fn(
 
 #define cfs_debug(...)  G_STMT_START { \
 	if (cfs.debug) \
-		cfs_log(CFS_LOG_UNKNOWN, G_LOG_LEVEL_DEBUG, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__); \
+		cfs_log(CFS_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__); \
 	} G_STMT_END
 
 #define cfs_dom_debug(domain, ...)  G_STMT_START {	\
@@ -108,9 +108,9 @@ void ipc_log_fn(
 		cfs_log(domain, G_LOG_LEVEL_DEBUG, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__); \
 	} G_STMT_END
 
-#define cfs_critical(...)  cfs_log(CFS_LOG_UNKNOWN, G_LOG_LEVEL_CRITICAL, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
+#define cfs_critical(...)  cfs_log(CFS_LOG_DOMAIN, G_LOG_LEVEL_CRITICAL, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
 #define cfs_dom_critical(domain, ...)  cfs_log(domain, G_LOG_LEVEL_CRITICAL, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
-#define cfs_message(...)  cfs_log(CFS_LOG_UNKNOWN, G_LOG_LEVEL_MESSAGE, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
+#define cfs_message(...)  cfs_log(CFS_LOG_DOMAIN, G_LOG_LEVEL_MESSAGE, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
 #define cfs_dom_message(domain, ...)  cfs_log(domain, G_LOG_LEVEL_MESSAGE, __FILE__, __LINE__, G_STRFUNC, __VA_ARGS__)
 
 guint64 
diff --git a/data/src/cfs-plug-func.c b/data/src/cfs-plug-func.c
index 8447923..f589a40 100644
--- a/data/src/cfs-plug-func.c
+++ b/data/src/cfs-plug-func.c
@@ -34,6 +34,8 @@
 #include <errno.h>
 #include <dirent.h>
 
+#define CFS_LOG_DOMAIN CFS_LOG_MAIN
+
 #include "cfs-utils.h"
 #include "cfs-plug.h"
 
diff --git a/data/src/cfs-plug-link.c b/data/src/cfs-plug-link.c
index 58d442d..39b4dbb 100644
--- a/data/src/cfs-plug-link.c
+++ b/data/src/cfs-plug-link.c
@@ -34,6 +34,8 @@
 #include <errno.h>
 #include <dirent.h>
 
+#define CFS_LOG_DOMAIN CFS_LOG_MAIN
+
 #include "cfs-utils.h"
 #include "cfs-plug.h"
 #include "status.h"
diff --git a/data/src/cfs-plug-memdb.c b/data/src/cfs-plug-memdb.c
index 901de7c..d9387a7 100644
--- a/data/src/cfs-plug-memdb.c
+++ b/data/src/cfs-plug-memdb.c
@@ -35,6 +35,8 @@
 #include <dirent.h>
 #include <arpa/inet.h>
 
+#define CFS_LOG_DOMAIN CFS_LOG_MAIN
+
 #include "cfs-utils.h"
 #include "cfs-plug-memdb.h"
 #include "dcdb.h"
diff --git a/data/src/cfs-plug.c b/data/src/cfs-plug.c
index 108ed6b..9e0d105 100644
--- a/data/src/cfs-plug.c
+++ b/data/src/cfs-plug.c
@@ -34,6 +34,8 @@
 #include <errno.h>
 #include <dirent.h>
 
+#define CFS_LOG_DOMAIN CFS_LOG_MAIN
+
 #include "cfs-utils.h"
 #include "cfs-plug.h"
 
diff --git a/data/src/cfs-utils.c b/data/src/cfs-utils.c
index 134c1cb..9d1905f 100644
--- a/data/src/cfs-utils.c
+++ b/data/src/cfs-utils.c
@@ -241,36 +241,36 @@ atomic_write_file(
 	char *tmp_name = g_strdup_printf ("%s.XXXXXX", filename);
 	int fd = mkstemp(tmp_name);
 	if (fd == -1) {
-		cfs_critical("Failed to create file '%s': %s", tmp_name, g_strerror(errno));
+		cfs_dom_critical(CFS_LOG_MAIN, "Failed to create file '%s': %s", tmp_name, g_strerror(errno));
 		res = FALSE;
 		goto ret;
 	}
 
 	if (fchown(fd, 0, gid) == -1) {
-		cfs_critical("Failed to change group of file '%s': %s", tmp_name, g_strerror(errno));
+		cfs_dom_critical(CFS_LOG_MAIN, "Failed to change group of file '%s': %s", tmp_name, g_strerror(errno));
 		close(fd);
 		goto fail;
 	}
 
 	if (fchmod(fd, mode) == -1) {
-		cfs_critical("Failed to change mode of file '%s': %s", tmp_name, g_strerror(errno));
+		cfs_dom_critical(CFS_LOG_MAIN, "Failed to change mode of file '%s': %s", tmp_name, g_strerror(errno));
 		close(fd);
 		goto fail;
 	}
 
 	if (len && !full_write(fd, data, len)) {
-		cfs_critical("Failed to write file '%s': %s", tmp_name, g_strerror(errno));
+		cfs_dom_critical(CFS_LOG_MAIN, "Failed to write file '%s': %s", tmp_name, g_strerror(errno));
 		close(fd);
 		goto fail;
 	}
 
 	if (close(fd) == -1) {
-		cfs_critical("Failed to close file '%s': %s", tmp_name, g_strerror(errno));
+		cfs_dom_critical(CFS_LOG_MAIN, "Failed to close file '%s': %s", tmp_name, g_strerror(errno));
 		goto fail;
 	}
 
 	if (rename(tmp_name, filename) == -1) {
-		cfs_critical("Failed to rename file from '%s' to '%s': %s", 
+		cfs_dom_critical(CFS_LOG_MAIN, "Failed to rename file from '%s' to '%s': %s", 
 			   tmp_name, filename, g_strerror(errno));
 		goto fail;
 	}
diff --git a/data/src/confdb.c b/data/src/confdb.c
index 7c4c992..c6aa72e 100644
--- a/data/src/confdb.c
+++ b/data/src/confdb.c
@@ -22,6 +22,7 @@
 /* see "man cmap_overview" and "man cmap_keys" */
 
 #define G_LOG_DOMAIN "confdb"
+#define CFS_LOG_DOMAIN CFS_LOG_CONFDB
 
 #define CLUSTER_KEY "cluster"
 
diff --git a/data/src/database.c b/data/src/database.c
index 8ce8852..dd1b563 100644
--- a/data/src/database.c
+++ b/data/src/database.c
@@ -19,6 +19,7 @@
 */
 
 #define G_LOG_DOMAIN "database"
+#define CFS_LOG_DOMAIN CFS_LOG_DB
 
 #ifdef HAVE_CONFIG_H
 #include <config.h>
diff --git a/data/src/dcdb.c b/data/src/dcdb.c
index b4f4359..4d32f9a 100644
--- a/data/src/dcdb.c
+++ b/data/src/dcdb.c
@@ -19,6 +19,7 @@
 */
 
 #define G_LOG_DOMAIN "dcdb"
+#define CFS_LOG_DOMAIN CFS_LOG_DCDB
 
 #ifdef HAVE_CONFIG_H
 #include <config.h>
diff --git a/data/src/dfsm.c b/data/src/dfsm.c
index ab761e1..ab7a9bc 100644
--- a/data/src/dfsm.c
+++ b/data/src/dfsm.c
@@ -520,7 +520,7 @@ dfsm_set_mode(
 {
 	g_return_if_fail(dfsm != NULL);
 
-	cfs_debug("dfsm_set_mode - set mode to %d", new_mode);
+	cfs_dom_debug(dfsm->log_domain, "dfsm_set_mode - set mode to %d", new_mode);
 
 	int changed = 0;
 	g_mutex_lock (&dfsm->mode_mutex);
@@ -592,7 +592,7 @@ dfsm_release_sync_resources(
 	g_return_if_fail(dfsm->members != NULL);
 	g_return_if_fail(!member_list_entries || member_list != NULL);
 
-	cfs_debug("enter dfsm_release_sync_resources");
+	cfs_dom_debug(dfsm->log_domain, "enter dfsm_release_sync_resources");
 
 	if (dfsm->sync_info) {
 
@@ -653,7 +653,9 @@ dfsm_cpg_deliver_callback(
 	dfsm_t *dfsm = NULL;
 	result = cpg_context_get(handle, (gpointer *)&dfsm);
 	if (result != CS_OK || !dfsm || dfsm->cpg_callbacks != &cpg_callbacks) {
-		cfs_critical("cpg_context_get error: %d (%p)", result, (void *) dfsm);
+		cfs_dom_critical(dfsm ? dfsm->log_domain : CFS_LOG_UNKNOWN,
+		                 "cpg_context_get error: %d (%p)",
+		                 result, (void *) dfsm);
 		return; /* we have no valid dfsm pointer, so we can just ignore this */
 	}
 	dfsm_mode_t mode = dfsm_get_mode(dfsm);
@@ -1111,7 +1113,9 @@ dfsm_cpg_confchg_callback(
 	dfsm_t *dfsm = NULL;
 	result = cpg_context_get(handle, (gpointer *)&dfsm);
 	if (result != CS_OK || !dfsm || dfsm->cpg_callbacks != &cpg_callbacks) {
-		cfs_critical("cpg_context_get error: %d (%p)", result, (void *) dfsm);
+		cfs_dom_critical(dfsm ? dfsm->log_domain : CFS_LOG_UNKNOWN,
+		                 "cpg_context_get error: %d (%p)",
+		                 result, (void *) dfsm);
 		return; /* we have no valid dfsm pointer, so we can just ignore this */
 	}
 
@@ -1323,7 +1327,7 @@ dfsm_verify_request(dfsm_t *dfsm)
 	iov[0].iov_base = (char *)&dfsm->csum_counter;
 	iov[0].iov_len = sizeof(dfsm->csum_counter);
 	
-	cfs_debug("send verify request %016" PRIX64, dfsm->csum_counter);
+	cfs_dom_debug(dfsm->log_domain, "send verify request %016" PRIX64, dfsm->csum_counter);
 
 	cs_error_t result;
 	result = dfsm_send_state_message_full(dfsm, DFSM_MESSAGE_VERIFY_REQUEST, iov, len);
diff --git a/data/src/logger.c b/data/src/logger.c
index 4cf9cce..47a789b 100644
--- a/data/src/logger.c
+++ b/data/src/logger.c
@@ -39,6 +39,8 @@
 
 #define SYSLOG_MAX_LINE_LENGTH 8192
 
+#define CFS_LOG_DOMAIN CFS_LOG_MAIN
+
 #include "cfs-utils.h"
 #include "logger.h"
 
diff --git a/data/src/loop.c b/data/src/loop.c
index 09c8590..59bb7be 100644
--- a/data/src/loop.c
+++ b/data/src/loop.c
@@ -19,6 +19,7 @@
 */
 
 #define G_LOG_DOMAIN "loop"
+#define CFS_LOG_DOMAIN CFS_LOG_LOOP
 
 #ifdef HAVE_CONFIG_H
 #include <config.h>
diff --git a/data/src/memdb.c b/data/src/memdb.c
index 33ea44d..2cf09b5 100644
--- a/data/src/memdb.c
+++ b/data/src/memdb.c
@@ -35,6 +35,8 @@
 #include <errno.h>
 #include <glib.h>
 
+#define CFS_LOG_DOMAIN CFS_LOG_MAIN
+
 #include "cfs-utils.h"
 #include "memdb.h"
 #include "status.h"
diff --git a/data/src/pmxcfs.c b/data/src/pmxcfs.c
index d5a3aac..00aa53d 100644
--- a/data/src/pmxcfs.c
+++ b/data/src/pmxcfs.c
@@ -46,6 +46,8 @@
 #include <qb/qbutil.h>
 #include <qb/qblog.h>
 
+#define CFS_LOG_DOMAIN CFS_LOG_MAIN
+
 #include "cfs-utils.h"
 #include "cfs-plug.h"
 #include "cfs-plug-memdb.h"
diff --git a/data/src/quorum.c b/data/src/quorum.c
index 0a75f7f..41126a0 100644
--- a/data/src/quorum.c
+++ b/data/src/quorum.c
@@ -19,6 +19,7 @@
 */
 
 #define G_LOG_DOMAIN "quorum"
+#define CFS_LOG_DOMAIN CFS_LOG_QUORUM
 
 #ifdef HAVE_CONFIG_H
 #include <config.h>
diff --git a/data/src/server.c b/data/src/server.c
index 549788a..214d6a9 100644
--- a/data/src/server.c
+++ b/data/src/server.c
@@ -19,6 +19,7 @@
 */
 
 #define G_LOG_DOMAIN "ipcs"
+#define CFS_LOG_DOMAIN CFS_LOG_IPCS
 
 #ifdef HAVE_CONFIG_H
 #include <config.h>
diff --git a/data/src/status.c b/data/src/status.c
index 004f02e..43d6763 100644
--- a/data/src/status.c
+++ b/data/src/status.c
@@ -19,6 +19,7 @@
 */
 
 #define G_LOG_DOMAIN "status"
+#define CFS_LOG_DOMAIN CFS_LOG_STATUS
 
 #ifdef HAVE_CONFIG_H
 #include <config.h>
-- 
2.20.1

[pve-devel] [PATCH cluster 3/3] pmxcfs: enable QB log thread

[Fabian Grünbichler]

since pmxcfs is a multi-threaded application, and `man qblog.h`
explicitly states:

 Thread safe non-blocking logging.

 Logging is only thread safe when threaded logging is in use. If you
 plan on logging from multiple threads, you must initialize libqb's
 logger thread and use qb_log_filter_ctl to set the QB_LOG_CONF_THREADED
 flag on all the logging targets in use.

without this we can lose log messages under high load, especially when
enabling debug mode to trouble-shoot issues.

Signed-off-by: Fabian Grünbichler <f.gruenbichler@proxmox.com>
---

Notes:
    this would have saved Alexandre and me quite a bit of back and forth and false
    leads ;)

 data/src/pmxcfs.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/data/src/pmxcfs.c b/data/src/pmxcfs.c
index 00aa53d..3146121 100644
--- a/data/src/pmxcfs.c
+++ b/data/src/pmxcfs.c
@@ -1005,8 +1005,13 @@ int main(int argc, char *argv[])
 		}
 	} else {
 		write_pidfile(getpid());
+		// foreground == STDERR logging enabled, make it threaded
+		qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_THREADED, QB_TRUE);
 	}
 
+	qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_THREADED, QB_TRUE);
+	qb_log_thread_start();
+
 	wrote_pidfile = TRUE;
 
 	cfs_loop_t *corosync_loop = cfs_loop_new(fuse);
-- 
2.20.1

Re: [pve-devel] [PATCH cluster 0/3] logging improvements

[Thomas Lamprecht]

On 01.10.20 10:53, Fabian Grünbichler wrote:
> noticed while debugging the (as it turns out) missing lock issue that
> qb_log is not thread-safe by default, this patch series switches to
> threaded, non-blocking logging.
> 
> Fabian Grünbichler (3):
>   pmxcfs: switch log domain to enum
>   pmxcfs: set log domain in more places
>   pmxcfs: enable QB log thread
> 
>  data/src/cfs-utils.h      | 36 ++++++++++++++++++++++++++++++++----
>  data/src/dfsm.h           |  6 +++---
>  data/src/loop.h           |  2 +-
>  data/src/cfs-plug-func.c  |  2 ++
>  data/src/cfs-plug-link.c  |  2 ++
>  data/src/cfs-plug-memdb.c |  2 ++
>  data/src/cfs-plug.c       |  2 ++
>  data/src/cfs-utils.c      | 16 ++++++++--------
>  data/src/confdb.c         |  3 ++-
>  data/src/database.c       |  1 +
>  data/src/dcdb.c           |  3 ++-
>  data/src/dfsm.c           | 18 +++++++++++-------
>  data/src/logger.c         |  2 ++
>  data/src/loop.c           | 11 ++++++-----
>  data/src/memdb.c          |  2 ++
>  data/src/pmxcfs.c         | 21 ++++++++++++---------
>  data/src/quorum.c         |  3 ++-
>  data/src/server.c         |  1 +
>  data/src/status.c         |  3 ++-
>  19 files changed, 95 insertions(+), 41 deletions(-)
> 

would need a rebase if we still want this