[RFE] logging: new way of defining and using log messages #3342

xhernandez · 2022-03-23T16:02:33Z

Messages from quiesce xlator have been migrated to the new format as an
example.

This new approach has several advantages:

Centralized message definition
Customizable list of additional data per message
Typed message arguments to enforce correctness
Consistency between different instances of the same message
Better uniformity in data type representation
Compile-time generation of messages
Easily modify the message and update all references
All argument preparation is done only if the message will be logged
Very easy to use
Code auto-completion friendly
All extra overhead is optimally optimized by gcc/clang

The main drawback is that it makes heavy use of some macros, which is
considered a bad practice sometimes, and it uses specific gcc/clang
extensions, but we are already using them in other places.

To create a new message:

GLFS_NEW(_comp, _name, _msg, _num, _fields...)

To deprecate an existing message:

GLFS_OLD(_comp, _name, _msg, _num, _fields...)

To permanently remove a message (but keep its ID reserved):

GLFS_GONE(_comp, _name, _msg, _num, _fields...)

To be able to mix messages using old and new interfaces, the messages
using the old interface can be defined this way:

GLFS_MIG(_comp, _name, _msg, _num, _fields...)

Each field is a list composed of the following elements:

(_type, _name, _source, _format, (_values) [, _extra])

_type is the data type of the field (int32_t, const char *, ...)
_name is the name of the field (it will also appear in the log
string)
_source is the origin of the data
_format is the C format string to represent the field
_values is a list of values used by _format (generally it's only
_name)
_extra is an optional extra code to prepare the representation of
the field (check GLFS_UUID() for an example)

There are some predefined macros for common data types.

Example:

Message definition:

GLFS_NEW(LIBGLUSTERFS, LG_MSG_EXAMPLE, "Example message", 3,
    GLFS_UINT(number),
    GLFS_ERR(error),
    GLFS_STR(name)
)

Message invocation:

GF_LOG_I("test", LG_MSG_EXAMPLE(3, -2, "test"));

This will generate a message like this:

"Example message ({number=3}, {error=2 (File not found)}, {name='test'})"

Debug and trace messages are defined directly in the logging place:

GF_LOG_D("test", "Debug message", 3,
    GLFS_UINT(number, 3),
    GLFS_ERR(error, errno),
    GLFS_STR(name, this->name)
);

Change-Id: I8f4bd7b9b90f649a52fe29a62222101eeccf0c68
Signed-off-by: Xavi Hernandez xhernandez@redhat.com

Messages from quiesce xlator have been migrated to the new format as an example. This new approach has several advantages: - Centralized message definition - Customizable list of additional data per message - Typed message arguments to enforce correctness - Consistency between different instances of the same message - Better uniformity in data type representation - Compile-time generation of messages - Easily modify the message and update all references - All argument preparation is done only if the message will be logged - Very easy to use - Code auto-completion friendly - All extra overhead is optimally optimized by gcc/clang The main drawback is that it makes heavy use of some macros, which is considered a bad practice sometimes, and it uses specific gcc/clang extensions, but we are already using them in other places. To create a new message: GLFS_NEW(_comp, _name, _msg, _num, _fields...) To deprecate an existing message: GLFS_OLD(_comp, _name, _msg, _num, _fields...) To permanently remove a message (but keep its ID reserved): GLFS_GONE(_comp, _name, _msg, _num, _fields...) Each field is a list composed of the following elements: (_type, _name, _format, (_values) [, _extra]) _type is the data type of the field (int32_t, const char *, ...) _name is the name of the field (it will also appear in the log string) _format is the C format string to represent the field _values is a list of values used by _format (generally it's only _name) _extra is an optional extra code to prepare the representation of the field (check GLFS_UUID() for an example) There are some predefined macros for common data types. Example: Message definition: GLFS_NEW(LIBGLUSTERFS, LG_MSG_EXAMPLE, "Example message", 3, GLFS_UINT(number), GLFS_ERROR(error), GLFS_STR(name) ) Message invocation: GF_LOG_I("test", LG_MSG_EXAMPLE(3, -2, "test")); This will generate a message like this: "Example message ({number=3}, {error=2 (File not found)}, {name='test'})" Change-Id: I8f4bd7b9b90f649a52fe29a62222101eeccf0c68 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

xhernandez · 2022-03-23T16:04:09Z

Let me know what do you think about this. I think it could be useful.

@mohit84 @mykaul @amarts @pranithk

gluster-ant · 2022-03-23T17:31:29Z

CLANG-FORMAT FAILURE:
Before merging the patch, this diff needs to be considered for passing clang-format

index d9b03f20e..09f88c5e8 100644
--- a/libglusterfs/src/glusterfs/glfs-message-id.h
+++ b/libglusterfs/src/glusterfs/glfs-message-id.h
@@ -110,9 +110,9 @@
  * defined at a time. Calling this macro for another component before finishing
  * the definition of messages for the previous component will mess the message
  * ids. */
-#define GLFS_COMPONENT(_name) \
-    enum { \
-        GLFS_##_name##_COMP_BASE = GLFS_MSGID_COMP_##_name - __COUNTER__ - 1 \
+#define GLFS_COMPONENT(_name)                                                  \
+    enum {                                                                     \
+        GLFS_##_name##_COMP_BASE = GLFS_MSGID_COMP_##_name - __COUNTER__ - 1   \
     }
 
 /* Unpack arguments. */
@@ -121,38 +121,37 @@
 /* These macros apply a macro to a list of 0..9 arguments. It can be extended
  * if more arguments are required. */
 
-#define GLFS_APPLY_0(_macro,  _in)
+#define GLFS_APPLY_0(_macro, _in)
 
-#define GLFS_APPLY_1(_macro, _in, _f) \
-    _macro _f
+#define GLFS_APPLY_1(_macro, _in, _f) _macro _f
 
-#define GLFS_APPLY_2(_macro, _in, _f, _more) \
+#define GLFS_APPLY_2(_macro, _in, _f, _more)                                   \
     _macro _f GLFS_EXPAND _in GLFS_APPLY_1(_macro, _in, _more)
 
-#define GLFS_APPLY_3(_macro, _in, _f, _more...) \
+#define GLFS_APPLY_3(_macro, _in, _f, _more...)                                \
     _macro _f GLFS_EXPAND _in GLFS_APPLY_2(_macro, _in, _more)
 
-#define GLFS_APPLY_4(_macro, _in, _f, _more...) \
+#define GLFS_APPLY_4(_macro, _in, _f, _more...)                                \
     _macro _f GLFS_EXPAND _in GLFS_APPLY_3(_macro, _in, _more)
 
-#define GLFS_APPLY_5(_macro, _in, _f, _more...) \
+#define GLFS_APPLY_5(_macro, _in, _f, _more...)                                \
     _macro _f GLFS_EXPAND _in GLFS_APPLY_4(_macro, _in, _more)
 
-#define GLFS_APPLY_6(_macro, _in, _f, _more...) \
+#define GLFS_APPLY_6(_macro, _in, _f, _more...)                                \
     _macro _f GLFS_EXPAND _in GLFS_APPLY_5(_macro, _in, _more)
 
-#define GLFS_APPLY_7(_macro, _in, _f, _more...) \
+#define GLFS_APPLY_7(_macro, _in, _f, _more...)                                \
     _macro _f GLFS_EXPAND _in GLFS_APPLY_6(_macro, _in, _more)
 
-#define GLFS_APPLY_8(_macro, _in, _f, _more...) \
+#define GLFS_APPLY_8(_macro, _in, _f, _more...)                                \
     _macro _f GLFS_EXPAND _in GLFS_APPLY_7(_macro, _in, _more)
 
-#define GLFS_APPLY_9(_macro, _in, _f, _more...) \
+#define GLFS_APPLY_9(_macro, _in, _f, _more...)                                \
     _macro _f GLFS_EXPAND _in GLFS_APPLY_8(_macro, _in, _more)
 
 /* Apply a macro to a variable number of fields. */
-#define GLFS_APPLY(_macro, _in, _num, _fields...) \
-    GLFS_APPLY_##_num(_macro, _in, ## _fields)
+#define GLFS_APPLY(_macro, _in, _num, _fields...)                              \
+    GLFS_APPLY_##_num(_macro, _in, ##_fields)
 
 /* Build a declaration for a structure from a field. */
 #define GLFS_FIELD(_type, _name, _extra...) _type _name;
@@ -167,110 +166,103 @@
 #define GLFS_ARG(_type, _name, _extra...) _type _name
 
 /* Initialize a variable from a field in a structure. */
-#define GLFS_VAR(_type, _name, _fmt, _data, _extra...) \
-    _type _name = _info->_name; _extra
+#define GLFS_VAR(_type, _name, _fmt, _data, _extra...)                         \
+    _type _name = _info->_name;                                                \
+    _extra
 
 /* Extract the data from a field. */
 #define GLFS_DATA(_type, _name, _fmt, _data, _extra...) , GLFS_EXPAND _data
 
 /* Generate the fields of the structre. */
-#define GLFS_FIELDS(_num, _fields...) \
-    GLFS_APPLY(GLFS_FIELD, (), _num, ## _fields)
+#define GLFS_FIELDS(_num, _fields...)                                          \
+    GLFS_APPLY(GLFS_FIELD, (), _num, ##_fields)
 
 /* Generate a list of the names of all fields. */
-#define GLFS_NAMES(_num, _fields...) \
-    GLFS_APPLY(GLFS_NAME, (), _num, ## _fields)
+#define GLFS_NAMES(_num, _fields...) GLFS_APPLY(GLFS_NAME, (), _num, ##_fields)
 
 /* Generate a format string for all fields. */
-#define GLFS_FMTS(_num, _fields...) \
-    GLFS_APPLY(GLFS_FMT, (", "), _num, ## _fields)
+#define GLFS_FMTS(_num, _fields...)                                            \
+    GLFS_APPLY(GLFS_FMT, (", "), _num, ##_fields)
 
 /* Generate the function call argument declaration for all fields. */
-#define GLFS_ARGS(_num, _fields...) \
-    GLFS_APPLY(GLFS_ARG, (,), _num, ## _fields)
+#define GLFS_ARGS(_num, _fields...) GLFS_APPLY(GLFS_ARG, (, ), _num, ##_fields)
 
 /* Generate the list of variables for all fields. */
-#define GLFS_VARS(_num, _fields...) \
-    GLFS_APPLY(GLFS_VAR, (), _num, ## _fields)
+#define GLFS_VARS(_num, _fields...) GLFS_APPLY(GLFS_VAR, (), _num, ##_fields)
 
 /* Generate the list of values from all fields. */
-#define GLFS_DATAS(_num, _fields...) \
-    GLFS_APPLY(GLFS_DATA, (), _num, ## _fields)
+#define GLFS_DATAS(_num, _fields...) GLFS_APPLY(GLFS_DATA, (), _num, ##_fields)
 
 /* Create the structure for a message. */
-#define GLFS_STRUCT(_name, _num, _fields...) \
-    struct _glfs_##_name { \
-        void (*_process)(const char *, const char *, const char *, uint32_t, \
-                         uint32_t, struct _glfs_##_name *); \
-        GLFS_FIELDS(_num, ## _fields) \
+#define GLFS_STRUCT(_name, _num, _fields...)                                   \
+    struct _glfs_##_name {                                                     \
+        void (*_process)(const char *, const char *, const char *, uint32_t,   \
+                         uint32_t, struct _glfs_##_name *);                    \
+        GLFS_FIELDS(_num, ##_fields)                                           \
     }
 
 /* Create the processing function for a message. */
-#define GLFS_PROCESS(_mod, _name, _msg, _num, _fields...) \
-    enum { _name##_ID = GLFS_##_mod##_COMP_BASE + __COUNTER__ }; \
-    _Static_assert((int)_name##_ID <= (int)GLFS_MSGID_COMP_##_mod##_END, \
-                   "Too many messages allocated for component " #_mod); \
-    extern inline __attribute__((__always_inline__)) void \
-    _glfs_process_##_name(const char *_dom, const char *_file, \
-                          const char *_func, uint32_t _line, uint32_t _level, \
-                          struct _glfs_##_name *_info) \
-    { \
-        GLFS_VARS(_num, ## _fields) \
-        _gf_log(_dom, _file, _func, _line, _level, "[MSGID:%u] " _msg " <" \
-                GLFS_FMTS(_num, ## _fields) ">", _name##_ID \
-                GLFS_DATAS(_num, ## _fields)); \
+#define GLFS_PROCESS(_mod, _name, _msg, _num, _fields...)                      \
+    enum { _name##_ID = GLFS_##_mod##_COMP_BASE + __COUNTER__ };               \
+    _Static_assert((int)_name##_ID <= (int)GLFS_MSGID_COMP_##_mod##_END,       \
+                   "Too many messages allocated for component " #_mod);        \
+    extern inline                                                              \
+        __attribute__((__always_inline__)) void _glfs_process_##_name(         \
+            const char *_dom, const char *_file, const char *_func,            \
+            uint32_t _line, uint32_t _level, struct _glfs_##_name *_info)      \
+    {                                                                          \
+        GLFS_VARS(_num, ##_fields)                                             \
+        _gf_log(_dom, _file, _func, _line, _level,                             \
+                "[MSGID:%u] " _msg " <" GLFS_FMTS(_num, ##_fields) ">",        \
+                _name##_ID GLFS_DATAS(_num, ##_fields));                       \
     }
 
 /* Create the data capture function for a message. */
-#define GLFS_CREATE(_name, _attr, _num, _fields...) \
-    extern inline __attribute__((__always_inline__, __warn_unused_result__)) \
-    _attr struct _glfs_##_name _name(GLFS_ARGS(_num, ## _fields)) \
-    { \
-        return (struct _glfs_##_name){ \
-            _glfs_process_##_name GLFS_NAMES(_num, ## _fields) \
-        }; \
+#define GLFS_CREATE(_name, _attr, _num, _fields...)                            \
+    extern inline __attribute__((__always_inline__, __warn_unused_result__))   \
+    _attr struct _glfs_##_name                                                 \
+    _name(GLFS_ARGS(_num, ##_fields))                                          \
+    {                                                                          \
+        return (struct _glfs_##_name){                                         \
+            _glfs_process_##_name GLFS_NAMES(_num, ##_fields)};                \
     }
 
 /* Create a new message. */
-#define GLFS_NEW(_mod, _name, _msg, _num, _fields...) \
-    GLFS_STRUCT(_name, _num, ## _fields); \
-    GLFS_PROCESS(_mod, _name, _msg, _num, ## _fields) \
-    GLFS_CREATE(_name,, _num, ## _fields)
+#define GLFS_NEW(_mod, _name, _msg, _num, _fields...)                          \
+    GLFS_STRUCT(_name, _num, ##_fields);                                       \
+    GLFS_PROCESS(_mod, _name, _msg, _num, ##_fields)                           \
+    GLFS_CREATE(_name, , _num, ##_fields)
 
 /* Create a deprecated message. */
-#define GLFS_OLD(_mod, _name, _msg, _num, _fields...) \
-    GLFS_STRUCT(_name, _num, ## _fields); \
-    GLFS_PROCESS(_mod, _name, _msg, _num, ## _fields) \
-    GLFS_CREATE(_name, __attribute__((__deprecated__)), _num, ## _fields)
+#define GLFS_OLD(_mod, _name, _msg, _num, _fields...)                          \
+    GLFS_STRUCT(_name, _num, ##_fields);                                       \
+    GLFS_PROCESS(_mod, _name, _msg, _num, ##_fields)                           \
+    GLFS_CREATE(_name, __attribute__((__deprecated__)), _num, ##_fields)
 
 /* Create a deleted message. */
-#define GLFS_GONE(_mod, _name, _msg, _num, _fields...) \
+#define GLFS_GONE(_mod, _name, _msg, _num, _fields...)                         \
     enum { _name##_ID_GONE = GLFS_##_mod##_COMP_BASE + __COUNTER__ };
 
 /* Helper to create an unsigned integer field. */
-#define GLFS_UINT(_name) \
-    (uint32_t, _name, "%" PRIu32, (_name))
+#define GLFS_UINT(_name) (uint32_t, _name, "%" PRIu32, (_name))
 
 /* Helper to create a signed integer field. */
-#define GLFS_INT(_name) \
-    (int32_t, _name, "%" PRId32, (_name))
+#define GLFS_INT(_name) (int32_t, _name, "%" PRId32, (_name))
 
 /* Helper to create an error field. */
-#define GLFS_ERROR(_name) \
+#define GLFS_ERROR(_name)                                                      \
     (int32_t, _name, "%" PRId32 " (%s)", (-_name, strerror(-_name)))
 
 /* Helper to create a string field. */
-#define GLFS_STR(_name) \
-    (const char *, _name, "'%s'", (_name))
+#define GLFS_STR(_name) (const char *, _name, "'%s'", (_name))
 
 /* Helper to create a gfid field. */
-#define GLFS_GFID(_name) \
-    (uuid_t *, _name, "%s", (*_name##_buff), \
-    char _name##_buff[48]; uuid_unparse(*_name, _name##_buff))
+#define GLFS_GFID(_name)                                                       \
+    (uuid_t *, _name, "%s", (*_name##_buff), char _name##_buff[48];            \
+     uuid_unparse(*_name, _name##_buff))
 
 /* Helper to create a pointer field. */
-#define GLFS_PTR(_name) \
-    (void *, _name, "%p", (_name))
+#define GLFS_PTR(_name) (void *, _name, "%p", (_name))
 
 /* Per module message segments allocated */
 /* NOTE: For any new module add to the end the modules */
diff --git a/libglusterfs/src/glusterfs/logging.h b/libglusterfs/src/glusterfs/logging.h
index 52c63ff89..235c1fade 100644
--- a/libglusterfs/src/glusterfs/logging.h
+++ b/libglusterfs/src/glusterfs/logging.h
@@ -341,20 +341,20 @@ _gf_smsg(const char *domain, const char *file, const char *function,
 
 /* Logging macro for messages created by GLFS_NEW(). It uses the same logic as
  * gf_log_get_loglevel() but inline and without requiring THIS. */
-#define GF_LOG(_xl, _lvl, _data) \
-    do { \
-        xlator_t *__log_xl = (_xl); \
-        const char *__log_name = ""; \
-        uint32_t __log_level = GF_LOG_INFO; \
-        if ((__log_xl != NULL) && (__log_xl->ctx != NULL)) { \
-            __log_name = __log_xl->name; \
-            __log_level = __log_xl->ctx->log.loglevel; \
-        } \
-        if (__log_level >= (_lvl)) { \
-            typeof(_data) __log_data = _data; \
-            __log_data._process(__log_name, __FILE__, __FUNCTION__, __LINE__, \
-                                _lvl, &__log_data); \
-        } \
+#define GF_LOG(_xl, _lvl, _data)                                               \
+    do {                                                                       \
+        xlator_t *__log_xl = (_xl);                                            \
+        const char *__log_name = "";                                           \
+        uint32_t __log_level = GF_LOG_INFO;                                    \
+        if ((__log_xl != NULL) && (__log_xl->ctx != NULL)) {                   \
+            __log_name = __log_xl->name;                                       \
+            __log_level = __log_xl->ctx->log.loglevel;                         \
+        }                                                                      \
+        if (__log_level >= (_lvl)) {                                           \
+            typeof(_data) __log_data = _data;                                  \
+            __log_data._process(__log_name, __FILE__, __FUNCTION__, __LINE__,  \
+                                _lvl, &__log_data);                            \
+        }                                                                      \
     } while (0)
 
 /* Shortcut macros for different log levels. */
diff --git a/xlators/features/quiesce/src/quiesce-messages.h b/xlators/features/quiesce/src/quiesce-messages.h
index bc75e9145..df8ae4f62 100644
--- a/xlators/features/quiesce/src/quiesce-messages.h
+++ b/xlators/features/quiesce/src/quiesce-messages.h
@@ -26,12 +26,9 @@
 GLFS_COMPONENT(QUIESCE);
 
 GLFS_NEW(QUIESCE, QUIESCE_MSG_INVAL_HOST, "Invalid internet address", 1,
-    GLFS_STR(address)
-)
+         GLFS_STR(address))
 
 GLFS_NEW(QUIESCE, QUIESCE_MSG_FAILOVER_FAILED, "Failed to initiate failover", 2,
-    GLFS_STR(host),
-    GLFS_ERROR(error)
-)
+         GLFS_STR(host), GLFS_ERROR(error))
 
 #endif /* __NL_CACHE_MESSAGES_H__ */

amarts

This is nice. More than how it is done, if I look at it as a consumer, this makes my life easy, guidelines for adding logs is clear, and would bring some hygiene in logging. I am in for having this infra added immediately, and pick up module by module, or fix logs whenever people want to pick would make it better.

amarts · 2022-03-23T18:07:00Z

xlators/features/quiesce/src/quiesce.c

@@ -130,8 +127,7 @@ gf_quiesce_failover_cbk(call_frame_t *frame, void *cookie, xlator_t *this,
         * just abort the failover attempts without retrying with other
         * hosts.
         */
-        gf_msg(this->name, GF_LOG_INFO, op_errno, QUIESCE_MSG_FAILOVER_FAILED,
-               "Initiating failover to host:%s failed:", (char *)cookie);
+        GF_LOG_I(this, QUIESCE_MSG_FAILOVER_FAILED(cookie, op_errno));


Nice! This will make people to 'Define' error log. Looks clean IMO.

Yes i also believe it is clean and easy to use.

Change-Id: Ic58135479f4713ddce07e71c539fe216d447d24e Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

gluster-ant · 2022-03-23T20:21:54Z

CLANG-FORMAT FAILURE:
Before merging the patch, this diff needs to be considered for passing clang-format

index 54da88f11..09f88c5e8 100644
--- a/libglusterfs/src/glusterfs/glfs-message-id.h
+++ b/libglusterfs/src/glusterfs/glfs-message-id.h
@@ -220,7 +220,8 @@
 /* Create the data capture function for a message. */
 #define GLFS_CREATE(_name, _attr, _num, _fields...)                            \
     extern inline __attribute__((__always_inline__, __warn_unused_result__))   \
-    _attr struct _glfs_##_name _name(GLFS_ARGS(_num, ##_fields))               \
+    _attr struct _glfs_##_name                                                 \
+    _name(GLFS_ARGS(_num, ##_fields))                                          \
     {                                                                          \
         return (struct _glfs_##_name){                                         \
             _glfs_process_##_name GLFS_NAMES(_num, ##_fields)};                \
diff --git a/libglusterfs/src/glusterfs/logging.h b/libglusterfs/src/glusterfs/logging.h
index 52c63ff89..235c1fade 100644
--- a/libglusterfs/src/glusterfs/logging.h
+++ b/libglusterfs/src/glusterfs/logging.h
@@ -341,20 +341,20 @@ _gf_smsg(const char *domain, const char *file, const char *function,
 
 /* Logging macro for messages created by GLFS_NEW(). It uses the same logic as
  * gf_log_get_loglevel() but inline and without requiring THIS. */
-#define GF_LOG(_xl, _lvl, _data) \
-    do { \
-        xlator_t *__log_xl = (_xl); \
-        const char *__log_name = ""; \
-        uint32_t __log_level = GF_LOG_INFO; \
-        if ((__log_xl != NULL) && (__log_xl->ctx != NULL)) { \
-            __log_name = __log_xl->name; \
-            __log_level = __log_xl->ctx->log.loglevel; \
-        } \
-        if (__log_level >= (_lvl)) { \
-            typeof(_data) __log_data = _data; \
-            __log_data._process(__log_name, __FILE__, __FUNCTION__, __LINE__, \
-                                _lvl, &__log_data); \
-        } \
+#define GF_LOG(_xl, _lvl, _data)                                               \
+    do {                                                                       \
+        xlator_t *__log_xl = (_xl);                                            \
+        const char *__log_name = "";                                           \
+        uint32_t __log_level = GF_LOG_INFO;                                    \
+        if ((__log_xl != NULL) && (__log_xl->ctx != NULL)) {                   \
+            __log_name = __log_xl->name;                                       \
+            __log_level = __log_xl->ctx->log.loglevel;                         \
+        }                                                                      \
+        if (__log_level >= (_lvl)) {                                           \
+            typeof(_data) __log_data = _data;                                  \
+            __log_data._process(__log_name, __FILE__, __FUNCTION__, __LINE__,  \
+                                _lvl, &__log_data);                            \
+        }                                                                      \
     } while (0)
 
 /* Shortcut macros for different log levels. */

Change-Id: Id2c74cc47478a956e00ffc6e8a99cac0c7d484c1 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Change-Id: I13eb3acb40daa78c545436808c40d11b41a763fc Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Change-Id: I19664fc29e3fbc74433049f8125d68cce571712a Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Change-Id: I293f6eb6abcd0ab4773456c62b2e1a3eeadf5b34 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Change-Id: I8ee35d7442840c27ae48a54875240945b3631acc Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Change-Id: Ic9d396c391bd40b4f16684b90e09e75741bef055 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Instead of passing the xlator, simply pass a name. This makes the code smaller. The current log level is taken from the 'global_ctx' instead of xlator->ctx. Change-Id: Icc2547285bfdba4dbc1d8f9c16efccdd377abe6e Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

xhernandez · 2022-03-24T19:01:34Z

/run regression

gluster-ant · 2022-03-24T22:13:19Z

1 test(s) failed
./tests/bugs/read-only/bug-1134822-read-only-default-in-graph.t

0 test(s) generated core

5 test(s) needed retry
./tests/000-flaky/basic_afr_split-brain-favorite-child-policy.t
./tests/000-flaky/glusterd-restart-shd-mux.t
./tests/bugs/cli/bug-1320388.t
./tests/bugs/quota/bug-1035576.t
./tests/bugs/read-only/bug-1134822-read-only-default-in-graph.t

1 flaky test(s) marked as success even though they failed
./tests/000-flaky/glusterd-restart-shd-mux.t
https://build.gluster.org/job/gh_centos7-regression/2288/

mohit84 · 2022-03-25T04:26:20Z

/run regression

dmantipov · 2022-03-25T07:27:35Z

What about unifying error messages through the whole system? For example, the following:

rpc/rpc-lib/src/rpcsvc.c:2569:
gf_log(GF_RPCSVC, GF_LOG_ERROR, "dict_set_str error");

xlators/features/read-only/src/worm-helper.c:51:
gf_log(this->name, GF_LOG_ERROR, "Error in setting the dict");

xlators/features/marker/src/marker-quota.c:735:
gf_log(this->name, GF_LOG_ERROR, "dict_set failed.");

has nearly the same meaning, and defining them 3 times (per-component, in two xlators and RPC layer) looks overengineered.

xhernandez · 2022-03-25T07:57:04Z

What about unifying error messages through the whole system? For example, the following:
rpc/rpc-lib/src/rpcsvc.c:2569:
gf_log(GF_RPCSVC, GF_LOG_ERROR, "dict_set_str error");

xlators/features/read-only/src/worm-helper.c:51:
gf_log(this->name, GF_LOG_ERROR, "Error in setting the dict");

xlators/features/marker/src/marker-quota.c:735:
gf_log(this->name, GF_LOG_ERROR, "dict_set failed.");
has nearly the same meaning, and defining them 3 times (per-component, in two xlators and RPC layer) looks overengineered.

This can be easily done with this new interface. You just need to define the messages in some shared header file and include it where necessary.

For DEBUG and TRACE messages we don't want to assign unique IDs because they may change easily. Instead those messages are defined in the same place where they are logged using a very similar interface. Updated the macros and documentation to support this change. Change-Id: I093d7c5bbca859d7b3d6445cef9091c1ee5df61a Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Change-Id: I19c00bd0816408b607746391437e07da2983fa06 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

gluster-ant · 2022-03-25T10:33:56Z

CLANG-FORMAT FAILURE:
Before merging the patch, this diff needs to be considered for passing clang-format

index 3c2fbfaf6..8364d68fe 100644
--- a/libglusterfs/src/glusterfs/glfs-message-id.h
+++ b/libglusterfs/src/glusterfs/glfs-message-id.h
@@ -129,25 +129,25 @@
     _macro _f GLFS_EXPAND _in GLFS_APPLY_1(_macro, _in, _more)
 
 #define GLFS_APPLY_3(_macro, _in, _f, _more...)                                \
-    _macro _f GLFS_EXPAND _in GLFS_APPLY_2(_macro, _in, ## _more)
+    _macro _f GLFS_EXPAND _in GLFS_APPLY_2(_macro, _in, ##_more)
 
 #define GLFS_APPLY_4(_macro, _in, _f, _more...)                                \
-    _macro _f GLFS_EXPAND _in GLFS_APPLY_3(_macro, _in, ## _more)
+    _macro _f GLFS_EXPAND _in GLFS_APPLY_3(_macro, _in, ##_more)
 
 #define GLFS_APPLY_5(_macro, _in, _f, _more...)                                \
-    _macro _f GLFS_EXPAND _in GLFS_APPLY_4(_macro, _in, ## _more)
+    _macro _f GLFS_EXPAND _in GLFS_APPLY_4(_macro, _in, ##_more)
 
 #define GLFS_APPLY_6(_macro, _in, _f, _more...)                                \
-    _macro _f GLFS_EXPAND _in GLFS_APPLY_5(_macro, _in, ## _more)
+    _macro _f GLFS_EXPAND _in GLFS_APPLY_5(_macro, _in, ##_more)
 
 #define GLFS_APPLY_7(_macro, _in, _f, _more...)                                \
-    _macro _f GLFS_EXPAND _in GLFS_APPLY_6(_macro, _in, ## _more)
+    _macro _f GLFS_EXPAND _in GLFS_APPLY_6(_macro, _in, ##_more)
 
 #define GLFS_APPLY_8(_macro, _in, _f, _more...)                                \
-    _macro _f GLFS_EXPAND _in GLFS_APPLY_7(_macro, _in, ## _more)
+    _macro _f GLFS_EXPAND _in GLFS_APPLY_7(_macro, _in, ##_more)
 
 #define GLFS_APPLY_9(_macro, _in, _f, _more...)                                \
-    _macro _f GLFS_EXPAND _in GLFS_APPLY_8(_macro, _in, ## _more)
+    _macro _f GLFS_EXPAND _in GLFS_APPLY_8(_macro, _in, ##_more)
 
 /* Apply a macro to a variable number of fields. */
 #define GLFS_APPLY(_macro, _in, _num, _fields...)                              \
@@ -187,8 +187,7 @@
     GLFS_APPLY(GLFS_FIELD, (), _num, ##_fields)
 
 /* Generate a list of the names of all fields. */
-#define GLFS_NAMES(_num, _fields...)                                           \
-    GLFS_APPLY(GLFS_NAME, (), _num, ##_fields)
+#define GLFS_NAMES(_num, _fields...) GLFS_APPLY(GLFS_NAME, (), _num, ##_fields)
 
 /* Generate a format string for all fields. */
 #define GLFS_FMTS(_num, _fields...)                                            \
@@ -244,16 +243,16 @@
     do {                                                                       \
         GLFS_COPIES(_num, ##_fields)                                           \
         _gf_log(_dom, __FILE__, __FUNCTION__, __LINE__, GF_LOG_DEBUG,          \
-                "[MSGID:DBG] " _msg " <" GLFS_FMTS(_num, ##_fields) ">"        \
-                GLFS_DATAS(_num, ##_fields));                                  \
+                "[MSGID:DBG] " _msg " <" GLFS_FMTS(                            \
+                    _num, ##_fields) ">" GLFS_DATAS(_num, ##_fields));         \
     } while (0)
 
 #define GLFS_TRACE(_dom, _msg, _num, _fields...)                               \
     do {                                                                       \
         GLFS_COPIES(_num, ##_fields)                                           \
         _gf_log(_dom, __FILE__, __FUNCTION__, __LINE__, GF_LOG_TRACE,          \
-                "[MSGID:TRC] " _msg " <" GLFS_FMTS(_num, ##_fields) ">"        \
-                GLFS_NAMES(_num, ##_fields));                                  \
+                "[MSGID:TRC] " _msg " <" GLFS_FMTS(                            \
+                    _num, ##_fields) ">" GLFS_NAMES(_num, ##_fields));         \
     } while (0)
 
 /* Create a new message. */
@@ -270,7 +269,7 @@
 
 /* Map a field name to its source. If source is not present, use the name */
 #define GLFS_MAP1(_dummy, _src, _data...) _src
-#define GLFS_MAP(_name, _src...) GLFS_MAP1(, ## _src, _name)
+#define GLFS_MAP(_name, _src...) GLFS_MAP1(, ##_src, _name)
 
 /* Create a deleted message. */
 #define GLFS_GONE(_mod, _name, _msg, _num, _fields...)                         \
@@ -278,36 +277,36 @@
 
 /* Helper to create an unsigned integer field. */
 #define GLFS_UINT(_name, _src...)                                              \
-    (uint32_t, _name, GLFS_MAP(_name, ## _src), "%" PRIu32, (GLFS_GET(_name)))
+    (uint32_t, _name, GLFS_MAP(_name, ##_src), "%" PRIu32, (GLFS_GET(_name)))
 
 /* Helper to create a signed integer field. */
 #define GLFS_INT(_name, _src...)                                               \
-    (int32_t, _name, GLFS_MAP(_name, ## _src), "%" PRId32, (GLFS_GET(_name)))
+    (int32_t, _name, GLFS_MAP(_name, ##_src), "%" PRId32, (GLFS_GET(_name)))
 
 /* Helper to create an error field. */
 #define GLFS_ERR(_name, _src...)                                               \
-    (int32_t, _name, GLFS_MAP(_name, ## _src), "%" PRId32 " (%s)",             \
+    (int32_t, _name, GLFS_MAP(_name, ##_src), "%" PRId32 " (%s)",              \
      (GLFS_GET(_name), strerror(GLFS_GET(_name))))
 
 /* Helper to create an error field where the error code is encoded in a
  * negative number. */
 #define GLFS_RES(_name, _src...)                                               \
-    (int32_t, _name, GLFS_MAP(_name, ## _src), "%" PRId32 " (%s)",             \
+    (int32_t, _name, GLFS_MAP(_name, ##_src), "%" PRId32 " (%s)",              \
      (-GLFS_GET(_name), strerror(-GLFS_GET(_name))))
 
 /* Helper to create a string field. */
 #define GLFS_STR(_name, _src...)                                               \
-    (const char *, _name, GLFS_MAP(_name, ## _src), "'%s'", (GLFS_GET(_name)))
+    (const char *, _name, GLFS_MAP(_name, ##_src), "'%s'", (GLFS_GET(_name)))
 
 /* Helper to create a gfid field. */
 #define GLFS_UUID(_name, _src...)                                              \
-    (const uuid_t *, _name, GLFS_MAP(_name, ## _src), "%s",                    \
+    (const uuid_t *, _name, GLFS_MAP(_name, ##_src), "%s",                     \
      (*GLFS_GET(_name##_buff)), char GLFS_GET(_name##_buff)[48];               \
      uuid_unparse(*GLFS_GET(_name), GLFS_GET(_name##_buff)))
 
 /* Helper to create a pointer field. */
 #define GLFS_PTR(_name, _src...)                                               \
-    (void *, _name, GLFS_MAP(_name, ## _src), "%p", (GLFS_GET(_name)))
+    (void *, _name, GLFS_MAP(_name, ##_src), "%p", (GLFS_GET(_name)))
 
 /* Per module message segments allocated */
 /* NOTE: For any new module add to the end the modules */
diff --git a/libglusterfs/src/glusterfs/logging.h b/libglusterfs/src/glusterfs/logging.h
index 26e943ed5..1215b1819 100644
--- a/libglusterfs/src/glusterfs/logging.h
+++ b/libglusterfs/src/glusterfs/logging.h
@@ -359,15 +359,15 @@ _gf_smsg(const char *domain, const char *file, const char *function,
 
 #define GF_LOG_D(_name, _msg, _num, _fields...)                                \
     do {                                                                       \
-        if (global_ctx->log.loglevel >= GF_LOG_DEBUG) {                              \
-            GLFS_DEBUG(_name, _msg, _num, ## _fields);                         \
+        if (global_ctx->log.loglevel >= GF_LOG_DEBUG) {                        \
+            GLFS_DEBUG(_name, _msg, _num, ##_fields);                          \
         }                                                                      \
     } while (0)
 
 #define GF_LOG_T(_name, _msg, _num, _fields...)                                \
     do {                                                                       \
-        if (global_ctx->log.loglevel >= GF_LOG_TRACE) {                              \
-            GLFS_TRACE(_name, _msg, _num, ## _fields);                         \
+        if (global_ctx->log.loglevel >= GF_LOG_TRACE) {                        \
+            GLFS_TRACE(_name, _msg, _num, ##_fields);                          \
         }                                                                      \
     } while (0)
 
diff --git a/xlators/features/quiesce/src/quiesce.c b/xlators/features/quiesce/src/quiesce.c
index 2a16eb0dd..70a864031 100644
--- a/xlators/features/quiesce/src/quiesce.c
+++ b/xlators/features/quiesce/src/quiesce.c
@@ -174,8 +174,10 @@ __gf_quiesce_perform_failover(xlator_t *this)
                         &priv->failover_list, list) {
                 failover_host->tried = 0;
         }*/
-        GF_LOG_D(this->name, "All the failover hosts have been tried and looks "
-                             "like didn't succeed", 0);
+        GF_LOG_D(this->name,
+                 "All the failover hosts have been tried and looks "
+                 "like didn't succeed",
+                 0);
         ret = -1;
         goto out;
     }

Added and documented support for a special macro to make it possible to incrementally migrate messages. Change-Id: I9878f453cd7ca13b20a2f04378283ffc808bdf95 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Change-Id: I7912981bb80d2cc799ebe16471d6aa0d911a3b0f Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

gluster-ant · 2022-03-25T11:43:08Z

CLANG-FORMAT FAILURE:
Before merging the patch, this diff needs to be considered for passing clang-format

index 15c893c35..a9efd2a3c 100644
--- a/libglusterfs/src/glusterfs/glfs-message-id.h
+++ b/libglusterfs/src/glusterfs/glfs-message-id.h
@@ -232,7 +232,8 @@
 /* Create the data capture function for a message. */
 #define GLFS_CREATE(_name, _attr, _num, _fields...)                            \
     static inline __attribute__((__always_inline__, __warn_unused_result__))   \
-    _attr struct _glfs_##_name _name(GLFS_ARGS(_num, ##_fields))               \
+    _attr struct _glfs_##_name                                                 \
+    _name(GLFS_ARGS(_num, ##_fields))                                          \
     {                                                                          \
         return (struct _glfs_##_name){                                         \
             _glfs_process_##_name GLFS_NAMES(_num, ##_fields)};                \

Change-Id: I159ca00ae30a81c147bb271cca596c161157fc50 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

xhernandez · 2022-03-25T12:26:05Z

/run regression

xhernandez · 2022-03-25T14:51:22Z

/run regression

aravindavk · 2022-03-25T17:39:00Z

This will generate a message like this:

"Example message ({number=3}, {error=2 (File not found)}, {name='test'})"

It is matching the existing structured logging format that we adopted for easy parsing. But can this be simplified to reduce the visual noise in logs?(Escaping double quotes is required) For example:

Example message.  number=3 error="2 (File not found)" name="test"

And a simple Python script like below can parse the log message.

import shlex

msg = 'Example message.  number=3 error="2 (File not found)" name="test"'
m, rest = msg.split("  ")

fields = {}
for kv in shlex.split(rest):
    k, v = kv.split("=", 1)
    fields[k] = v

gluster-ant · 2022-03-25T18:04:14Z

1 test(s) failed
./tests/bugs/distribute/bug-1286171.t

0 test(s) generated core

7 test(s) needed retry
./tests/000-flaky/basic_afr_split-brain-favorite-child-policy.t
./tests/000-flaky/basic_mount-nfs-auth.t
./tests/000-flaky/bugs_nfs_bug-1116503.t
./tests/basic/ec/self-heal.t
./tests/basic/shd-mux-ec.t
./tests/bugs/changelog/bug-1208470.t
./tests/bugs/distribute/bug-1286171.t

2 flaky test(s) marked as success even though they failed
./tests/000-flaky/basic_mount-nfs-auth.t
./tests/000-flaky/bugs_nfs_bug-1116503.t
https://build.gluster.org/job/gh_centos7-regression/2293/

xhernandez · 2022-03-28T10:40:06Z

/run regression

xhernandez · 2022-03-28T12:01:35Z

This will generate a message like this:
"Example message ({number=3}, {error=2 (File not found)}, {name='test'})"
It is matching the existing structured logging format that we adopted for easy parsing. But can this be simplified to reduce the visual noise in logs?(Escaping double quotes is required) For example:
Example message.  number=3 error="2 (File not found)" name="test"
And a simple Python script like below can parse the log message.
import shlex

msg = 'Example message.  number=3 error="2 (File not found)" name="test"'
m, rest = msg.split("  ")

fields = {}
for kv in shlex.split(rest):
    k, v = kv.split("=", 1)
    fields[k] = v

I don't think it's so easy. Your python script will break as soon as a message or any of the data fields included contains two consecutive spaces. Also, shlex.split() requires that data that is not really a string, like an error and its message, needs to be logged as a string.

You can easily do something very similar with the current format:

m, rest = msg.split('<{', 1)

fields = {}
for kv in rest[:-2].split('}, {'):
    k, v = kv.split('=', 1)
    fields[k] = v

I don't think the current format adds too much noise, and the extra symbols could be used to parse data more strictly if necessary, but I'm not against changing it if others also think it would be better.

xhernandez · 2022-04-05T10:27:23Z

If there isn't any additional issue or concern, I'll merge this by the end of this week.

xhernandez added Type:Enhancement DO-NOT-MERGE This is equivalent to '-2' on Gerrit. labels Mar 23, 2022

amarts reviewed Mar 23, 2022

View reviewed changes

Fixed clang-format issues

2ea5bac

Change-Id: Ic58135479f4713ddce07e71c539fe216d447d24e Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

xhernandez added 7 commits March 24, 2022 09:38

Fix more clang-format issues

e81c5de

Change-Id: Id2c74cc47478a956e00ffc6e8a99cac0c7d484c1 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Fix compilation issues with older gcc

724b334

Change-Id: I13eb3acb40daa78c545436808c40d11b41a763fc Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Change message ID name

58eb50c

Change-Id: I19664fc29e3fbc74433049f8125d68cce571712a Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Modify templates for creating messages

32865fe

Change-Id: I293f6eb6abcd0ab4773456c62b2e1a3eeadf5b34 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Updated documentation

7c8099c

Change-Id: I8ee35d7442840c27ae48a54875240945b3631acc Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Added a new error type for negative errors

fa11b47

Change-Id: Ic9d396c391bd40b4f16684b90e09e75741bef055 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

mykaul mentioned this pull request Mar 24, 2022

Multiple files: call logger function for TRACE and DEBUG levels only … #2870

Closed

xhernandez added 2 commits March 25, 2022 11:06

Renamed missed GLFS_ERROR to GLFS_ERR

f8f55ff

Change-Id: I19c00bd0816408b607746391437e07da2983fa06 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

xhernandez added 2 commits March 25, 2022 12:21

Added macros for easy migration

eed0dae

Added and documented support for a special macro to make it possible to incrementally migrate messages. Change-Id: I9878f453cd7ca13b20a2f04378283ffc808bdf95 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Fix clang-format issues

ec2b0d1

Change-Id: I7912981bb80d2cc799ebe16471d6aa0d911a3b0f Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

Fix clang-format issues once again

1815890

Change-Id: I159ca00ae30a81c147bb271cca596c161157fc50 Signed-off-by: Xavi Hernandez <xhernandez@redhat.com>

xhernandez marked this pull request as ready for review March 28, 2022 15:08

xhernandez removed the DO-NOT-MERGE This is equivalent to '-2' on Gerrit. label Mar 28, 2022

amarts approved these changes Apr 4, 2022

View reviewed changes

xhernandez merged commit 30a79e9 into gluster:devel Apr 8, 2022

xhernandez deleted the new_logging branch April 8, 2022 16:58

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[RFE] logging: new way of defining and using log messages #3342

[RFE] logging: new way of defining and using log messages #3342

xhernandez commented Mar 23, 2022 •

edited

xhernandez commented Mar 23, 2022

gluster-ant commented Mar 23, 2022

amarts left a comment

amarts Mar 23, 2022

mohit84 Mar 25, 2022

gluster-ant commented Mar 23, 2022

xhernandez commented Mar 24, 2022

gluster-ant commented Mar 24, 2022

mohit84 commented Mar 25, 2022

dmantipov commented Mar 25, 2022

xhernandez commented Mar 25, 2022

gluster-ant commented Mar 25, 2022

gluster-ant commented Mar 25, 2022

xhernandez commented Mar 25, 2022

xhernandez commented Mar 25, 2022

aravindavk commented Mar 25, 2022

gluster-ant commented Mar 25, 2022

xhernandez commented Mar 28, 2022

xhernandez commented Mar 28, 2022

xhernandez commented Apr 5, 2022

[RFE] logging: new way of defining and using log messages #3342

[RFE] logging: new way of defining and using log messages #3342

Conversation

xhernandez commented Mar 23, 2022 • edited

xhernandez commented Mar 23, 2022

gluster-ant commented Mar 23, 2022

amarts left a comment

Choose a reason for hiding this comment

amarts Mar 23, 2022

Choose a reason for hiding this comment

mohit84 Mar 25, 2022

Choose a reason for hiding this comment

gluster-ant commented Mar 23, 2022

xhernandez commented Mar 24, 2022

gluster-ant commented Mar 24, 2022

mohit84 commented Mar 25, 2022

dmantipov commented Mar 25, 2022

xhernandez commented Mar 25, 2022

gluster-ant commented Mar 25, 2022

gluster-ant commented Mar 25, 2022

xhernandez commented Mar 25, 2022

xhernandez commented Mar 25, 2022

aravindavk commented Mar 25, 2022

gluster-ant commented Mar 25, 2022

xhernandez commented Mar 28, 2022

xhernandez commented Mar 28, 2022

xhernandez commented Apr 5, 2022

xhernandez commented Mar 23, 2022 •

edited