Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Structured logging format support #657

Closed
aravindavk opened this issue Apr 12, 2019 · 42 comments
Closed

Structured logging format support #657

aravindavk opened this issue Apr 12, 2019 · 42 comments
Labels
DocApproved Mandatory flag to pass smoke. Provide user facing document to get approval. FA: Debug-ability & Quality FA: Usability & Supportability SpecApproved This is a mandatory flag for passing the smoke for feature. Provide spec of feature to get approval wontfix Managed by stale[bot]
Milestone

Comments

@aravindavk
Copy link
Member

Convert existing gf_log and gf_msg logs into gf_slog and gf_smsg format to support structured logging.

Number of log entries using `gf_log`:          2439 (`grep -R "gf_log(" * | wc -l`)
Number of log entries using `gf_msg`:          7501 (`grep -R "gf_msg(" * | wc -l`)
Number of log entries already using `gf_slog`:    4 (`grep -R "gf_slog(" * | wc -l`)
Number of log entries already using `gf_smsg`:   80 (`grep -R "gf_smsg(" * | wc -l`)

Ref: http://aravindavk.in/blog/gluster-log-tools-and-structured-logging/

While migrating to the new format we need to identify missing fields and other improvements

Missing log fields

Some of the log messages are not at all useful because it will not provide enough details. For example, reset a volume option and observe the log,

[2019-02-26 12:32:30.186698] I [MSGID: 0] [glusterd-handler.c:1933:__glusterd_handle_reset_volume] 0-management: Received reset vol req

The message says received the reset request but will not say to which volume or which option is reset.

Cryptic error messages

If an issue can be ignored then do not log as an error. Or if a message is logged as an error then it should be self-explanatory. For example, the following message in glusterd log is not providing the information about what is the handler and what to do if dispatch is failed.

[2019-02-26 12:48:44.031709] E [MSGID: 101191] [event-epoll.c:765:event_dispatch_epoll_worker] 0-epoll: Failed to dispatch handler

Proper Log levels

Unnecessary log messages

If an operation is internal and it is already in the expected state then logging can be skipped. For example, trying to stop some internal services which are already stopped. (or it can be changed to DEBUG)

[2019-02-26 12:48:44.029180] I [MSGID: 106131] [glusterd-proc-mgmt.c:86:glusterd_proc_stop] 0-management: scrub already stopped
@mykaul
Copy link
Contributor

mykaul commented Apr 14, 2019

@aravindavk - can you write documentation for developers, 'how to convert your message to structured' ?

@aravindavk
Copy link
Member Author

@aravindavk - can you write documentation for developers, 'how to convert your message to structured' ?

Ack. I will update this issue with details about how to convert a message to structured.

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/22987 has been posted that references this issue.

logging: Structured logging reference PR

  • Static part of Log message is defined in header(*-messages.h)
    Note: Enum list can be removed later once all migration complete
    to avoid changed Message IDs for existing log messages

    #define LOG_MSG_REMOTE_OP_FAILED "remote operation failed."

  • Change gf_msg to use gf_slog. Convert values into fields and
    add any missing fields. Note: errno and error fields will be
    added automatically to log message in case errnum is specified.

    Example:

    gf_slog(
    this->name, // Name or log domain
    GF_LOG_WARNING, // Log Level
    rsp.op_errno, // Error number
    LOG_REMOTE_OP_FAILED, // Static Log Message
    "path=%s", local->loc.path, // Key Value 1
    "gfid=%s", loc_gfid_utoa(&local->loc), // Key Value 2
    NULL // Log End
    );

Key value pairs formatting Help:

gf_slog(
this->name, // Name or log domain
GF_LOG_WARNING, // Log Level
rsp.op_errno, // Error number
LOG_OP_FAILED, // Static Log Message
"op=CREATE", // Static Key and Value
"path=%s", local->loc.path, // Format for Value
"brick-%d-status=%s", brkidx, brkstatus, // Use format for key and val
NULL // Log End
);

Before:

[2019-07-03 08:16:18.226819] W [MSGID: 114031] [client-rpc-fops_v2.c
:2633:client4_0_lookup_cbk] 0-gv3-client-0: remote operation failed.
Path: / (00000000-0000-0000-0000-000000000001) [Transport endpoint
is not connected]

After:

[2019-07-03 15:09:59.949682] W [client-rpc-fops_v2.c:2633:client4_0_lookup_cbk]
0-gv3-client-0: remote operation failed. path=/hello1.txt
gfid=00000000-0000-0000-0000-000000000000 errno=107
error="Transport endpoint is not connected"

Message ID is redundant since message part is static and values
are represented as key value pairs.

Change-Id: I4e7d37f27f106ab398e991d931ba2ac7841a44b1
Updates: #657
Signed-off-by: Aravinda VK avishwan@redhat.com

@amarts amarts added DocApproved Mandatory flag to pass smoke. Provide user facing document to get approval. SpecApproved This is a mandatory flag for passing the smoke for feature. Provide spec of feature to get approval labels Jul 4, 2019
gluster-ant pushed a commit that referenced this issue Aug 20, 2019
To convert the existing `gf_msg` to `gf_smsg`:

- Define `_STR` of respective Message ID as below(In `*-messages.h`)

  #define PC_MSG_REMOTE_OP_FAILED_STR "remote operation failed."

- Change `gf_msg` to use `gf_smsg`. Convert values into fields and
  add any missing fields. Note: `errno` and `error` fields will be
  added automatically to log message in case errnum is specified.

  Example:

  gf_smsg(
    this->name,                            // Name or log domain
    GF_LOG_WARNING,                        // Log Level
    rsp.op_errno,                          // Error number
    PC_MSG_REMOTE_OP_FAILED,               // Message ID
    "path=%s", local->loc.path,            // Key Value 1
    "gfid=%s", loc_gfid_utoa(&local->loc), // Key Value 2
    NULL                                   // Log End
  );

Key value pairs formatting Help:

  gf_slog(
    this->name,                               // Name or log domain
    GF_LOG_WARNING,                           // Log Level
    rsp.op_errno,                             // Error number
    PC_MSG_REMOTE_OP_FAILED,                  // Message ID
    "op=CREATE",                              // Static Key and Value
    "path=%s", local->loc.path,               // Format for Value
    "brick-%d-status=%s", brkidx, brkstatus,  // Use format for key and val
    NULL                                      // Log End
  );

Before:

[2019-07-03 08:16:18.226819] W [MSGID: 114031] [client-rpc-fops_v2.c \
:2633:client4_0_lookup_cbk] 0-gv3-client-0: remote operation failed. \
Path: / (00000000-0000-0000-0000-000000000001) [Transport endpoint   \
is not connected]

After:

[2019-07-29 07:50:15.773765] W [MSGID: 114031]                   \
[client-rpc-fops_v2.c:2633:client4_0_lookup_cbk] 0-gv1-client-0: \
remote operation failed. [{path=/f1},                            \
{gfid=00000000-0000-0000-0000-000000000000},                     \
{errno=107}, {error=Transport endpoint is not connected}]

To add new `gf_smsg`, Add a Message ID in respective `*-messages.h` file
and the follow the steps mentioned above.

Change-Id: I4e7d37f27f106ab398e991d931ba2ac7841a44b1
Updates: #657
Signed-off-by: Aravinda VK <avishwan@redhat.com>
@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23280 has been posted that references this issue.

geo-rep: Structured logging new format

Structured logging format changed in the below patch for better
readability and parsing. This patch changes the Geo-replication logs
to that format.

https://review.gluster.org/#/c/glusterfs/+/22987/

Before:

[2019-08-21 04:23:01.13672] I [monitor(monitor):157:monitor] Monitor: \
  starting gsyncd worker<TAB>brick=/bricks/b1<TAB>slave_node=f29.sonne

After:

[2019-08-21 04:23:01.13672] I [monitor(monitor):157:monitor] Monitor: \
  starting gsyncd worker [{brick=/bricks/b1}, {slave_node=f29.sonne}]

Change-Id: I65ec69a2869e2febeedc558f88620399e4a1a6a4
Updates: #657
Signed-off-by: Aravinda VK avishwan@redhat.com

gluster-ant pushed a commit that referenced this issue Aug 21, 2019
Structured logging format changed in the below patch for better
readability and parsing. This patch changes the Geo-replication logs
to that format.

https://review.gluster.org/#/c/glusterfs/+/22987/

Before:

```
[2019-08-21 04:23:01.13672] I [monitor(monitor):157:monitor] Monitor: \
  starting gsyncd worker<TAB>brick=/bricks/b1<TAB>slave_node=f29.sonne
```

After:

```
[2019-08-21 04:23:01.13672] I [monitor(monitor):157:monitor] Monitor: \
  starting gsyncd worker [{brick=/bricks/b1}, {slave_node=f29.sonne}]
```

Change-Id: I65ec69a2869e2febeedc558f88620399e4a1a6a4
Updates: #657
Signed-off-by: Aravinda VK <avishwan@redhat.com>
@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23535 has been posted that references this issue.

logging: structured logging PR

To convert the existing 'gf_msg' to 'gf_smsg'

Updates: #657

Change-Id: I930f771ba6c7141504c24d8848c8cba3d9b43c5b

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23636 has been posted that references this issue.

afr: structure logging

All the gf_msg() has been converted to gf_smsg()

Change-Id: I34f15981c9c83fe0895b55489928172907b402a7
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23652 has been posted that references this issue.

afr_inode/xlator: structure logging

convert gf_msg() into gf_smsg()

Change-Id: I8f5b7bbb9caa78902b06f67257502b67adab7405
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23680 has been posted that references this issue.

glusterfsd: structure logging

convert gf_msg() to gf_smsg()

Change-Id: I1cd6a5ac6f4361195d5d925efb2cc194045d0bba
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23689 has been posted that references this issue.

glusterfsd-mgmt: Structure logging

convert gf_msg() to gf_smsg()

Change-Id: I1d760a37b811dcb42339cd25b909391f8a4e4635
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23693 has been posted that references this issue.

libglusterfs_inode: structure logging

convert gf_msg() to gf_smsg()

Change-Id: I44d9859a0f17b28ceacfcfd10c78bfd723ca4d43
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23715 has been posted that references this issue.

libglusterfs/common-utils: structure logging

changes all the gf_msg() to gf_smgs()

Change-Id: I3524bbd8f8070df2f2c888ea9b0fb7db1ee44453
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23693 has been posted that references this issue.

libglusterfs_inode: structure logging

convert gf_msg() to gf_smsg()

Change-Id: I44d9859a0f17b28ceacfcfd10c78bfd723ca4d43
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23726 has been posted that references this issue.

libglusterfs-xlator: structure logging

convert all gf_msg() to gf_smsg()

Change-Id: Id542e05faadb8041b472a2298c71fe62730e65fc
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23746 has been posted that references this issue.

libglusterfs-event-epoll: structure logging

convert gf_msg() to gf_smsg()

Change-Id: Idf5bfc826b0c9f1a2674eea2a2e6164f30806b00
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23748 has been posted that references this issue.

libglusterfs-options: structure logging

convert all gf_msg() to gf_smsg()

Change-Id: I8f1ff462b9c8012ed676c51450930a65ac403bf3
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23754 has been posted that references this issue.

api-glfs-fops: structure logging

Convert gf_msg() to gf_smsg()

Change-Id: Iceb40d60a75106c7b4b0a2487b611f7376bccc46
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23804 has been posted that references this issue.

xlator/changelog: structure logging

convert all gf_msg() to gf_smsg()

Change-Id: I2303aeaa0775b663e2ea5741166a457cd747d2ac
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23805 has been posted that references this issue.

xlator/dht: structure logging

convert all gf_msg() to gf_smsg()

Change-Id: I23eb86971f957a8f3a3aa0ea2bc1ee93dd6b6103
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23848 has been posted that references this issue.

xlator/dht-continue: structure logging

Convert gf_msg() to gf_smsg()

Change-Id: Ic72f2513e641cfcbe074933cb2697ee9fc05a766
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23853 has been posted that references this issue.

xlator/dht-lock: structure logging

convert gf_msg() to gf_smsg()

Change-Id: If540ca921b1cd8ca75b92b3d72eb9eb61bdaaa10
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23854 has been posted that references this issue.

xlator/dht-layout: structure logging

convert gf_msg() to gf_smsg()

Change-Id: I39b2043e4d63a9d9dae77b02ac57d7b37f8518b0
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23856 has been posted that references this issue.

xlator/dht-common: structure logging

convert gf_msg() to gf_smsg()

Change-Id: If034c4079e1fbcf0ede9fef23c3d018d31739d7a
Updates: #657

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/23857 has been posted that references this issue.

xlator/dht-helper: structure logging

convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: Iab35ac89b7d7fb6fb0074fc61b11bf679c517c9d
Signed-off-by: yatipadia ypadia@redhat.com

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/24066 has been posted that references this issue.

protocol/client-handshake: structure logging

convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: Iee07228cfc3a9a9cd10e89ae9eb918681b072585
Signed-off-by: yatip ypadia@redhat.com

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/24076 has been posted that references this issue.

protocol/client: structure logging

convert all gf_msg() to gf_smsg()

Updates: #657

Change-Id: I69b228d7c7a8bc6263f9bd33710e880678d8c017
Signed-off-by: yatip ypadia@redhat.com

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/24082 has been posted that references this issue.

protocol/client-rpc-fops: structure logging

convert all gf_msg() to gf_smsg()

Updates: #657

Change-Id: Ia9d4fb17579af6586bc13d69ec7990c6cf220aac
Signed-off-by: yatip ypadia@redhat.com

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/24089 has been posted that references this issue.

protocol/client: structure logging

convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: I76a09cfd283bb4ec5c4358536da66547aaf0de31
Signed-off-by: yatip ypadia@redhat.com

gluster-ant pushed a commit that referenced this issue Feb 4, 2020
convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: Ib45f121f583c2af09bfddb23391f73a117e63213
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 4, 2020
convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: Iee07228cfc3a9a9cd10e89ae9eb918681b072585
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 4, 2020
convert all gf_msg() to gf_smsg()

Updates: #657

Change-Id: I69b228d7c7a8bc6263f9bd33710e880678d8c017
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 4, 2020
convert all gf_msg() to gf_smsg()

Updates: #657

Change-Id: I9104ba8a8102f04d031a208abb06b6cf8ea8fd13
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 4, 2020
changes all the gf_msg() to gf_smgs()

Change-Id: I3524bbd8f8070df2f2c888ea9b0fb7db1ee44453
Updates: #657
Signed-off-by: yatipadia <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 4, 2020
convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: I2dd09a205c11d1c05abc7106e67802d2aa3bca79
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 4, 2020
convert all gf_msg() to gf_smsg()

Change-Id: Ifa45b5089f83ddfcf69132bb8d9c0dc6d012464b
Updates: #657
Signed-off-by: yatipadia <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 5, 2020
Convert gf_msg() to gf_smsg()

Change-Id: Ic72f2513e641cfcbe074933cb2697ee9fc05a766
Updates: #657
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 6, 2020
convert all gf_msg() to gf_smsg()

Updates: #657

Change-Id: Ia9d4fb17579af6586bc13d69ec7990c6cf220aac
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 6, 2020
convert gf_msg() to gf_smsg()

Change-Id: I1cd6a5ac6f4361195d5d925efb2cc194045d0bba
Updates: #657
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 6, 2020
convert gf_msg() to gf_smsg()

Change-Id: Idf5bfc826b0c9f1a2674eea2a2e6164f30806b00
Updates: #657
Signed-off-by: yatipadia <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 9, 2020
convert all gf_msg() to gf_smsg()

Change-Id: I8f1ff462b9c8012ed676c51450930a65ac403bf3
Updates: #657
Signed-off-by: yatipadia <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Feb 14, 2020
convert all gf_msg() to gf_smsg()

Change-Id: Id542e05faadb8041b472a2298c71fe62730e65fc
Updates: #657
Signed-off-by: yatipadia <ypadia@redhat.com>
@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/24154 has been posted that references this issue.

protocol/server: structure logging

Convert all gf_msg() to gf_smsg()

Updates: #657
Change-Id: Ic54b03f05e2766c87f50df0b3a66803b5519fad9
Signed-off-by: yatip ypadia@redhat.com

gluster-ant pushed a commit that referenced this issue Feb 26, 2020
convert gf_msg() to gf_smsg()

Change-Id: If540ca921b1cd8ca75b92b3d72eb9eb61bdaaa10
Updates: #657
Signed-off-by: yatip <ypadia@redhat.com>
@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/24179 has been posted that references this issue.

protocol/server-rpc-fops_v2: structure logging

convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: I01146bcd06bca44faeca29da48fab1ee3fc51e00
Signed-off-by: yatip ypadia@redhat.com

@gluster-ant
Copy link
Collaborator

A patch https://review.gluster.org/24185 has been posted that references this issue.

protocol/server-helpers: structure logging

convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: Ic7b38b646fa0932f7c1562467866137c4567e1f1
Signed-off-by: yatip ypadia@redhat.com

gluster-ant pushed a commit that referenced this issue Mar 3, 2020
Convert all gf_msg() to gf_smsg()

Updates: #657
Change-Id: Ic54b03f05e2766c87f50df0b3a66803b5519fad9
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Mar 3, 2020
convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: I01146bcd06bca44faeca29da48fab1ee3fc51e00
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Mar 3, 2020
convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: Ic7b38b646fa0932f7c1562467866137c4567e1f1
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Mar 3, 2020
convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: I76a09cfd283bb4ec5c4358536da66547aaf0de31
Signed-off-by: yatip <ypadia@redhat.com>
gluster-ant pushed a commit that referenced this issue Mar 3, 2020
convert gf_msg() to gf_smsg()

Updates: #657

Change-Id: Iab35ac89b7d7fb6fb0074fc61b11bf679c517c9d
Signed-off-by: yatipadia <ypadia@redhat.com>
Signed-off-by: yatip <ypadia@redhat.com>
@stale
Copy link

stale bot commented Dec 2, 2020

Thank you for your contributions.
Noticed that this issue is not having any activity in last ~6 months! We are marking this issue as stale because it has not had recent activity.
It will be closed in 2 weeks if no one responds with a comment here.

@stale stale bot added the wontfix Managed by stale[bot] label Dec 2, 2020
@stale
Copy link

stale bot commented Dec 17, 2020

Closing this issue as there was no update since my last update on issue. If this is an issue which is still valid, feel free to open it.

@stale stale bot closed this as completed Dec 17, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
DocApproved Mandatory flag to pass smoke. Provide user facing document to get approval. FA: Debug-ability & Quality FA: Usability & Supportability SpecApproved This is a mandatory flag for passing the smoke for feature. Provide spec of feature to get approval wontfix Managed by stale[bot]
Projects
None yet
Development

No branches or pull requests

4 participants