Nithya Balachandran
2014-Apr-30 07:06 UTC
[Gluster-users] GlusterFS and the logging framework
Hi,
I have attached some DHT files to demonstrate the 2 logging approaches. (*_1 is
the original approach, *_2 is the proposed approach).I personally think the 2
approach leads to better code readability and propose that we follow approach 2.
Please let me know of any concerns with this.
To consolidate all the points raised in the earlier discussions:
What are we trying to solve?
Improving gluster logs to make end user debugging easier by providing a
sufficient information and a consistent logging mechanism and message format .
The new logging framework already logs the function name and line, msgid and
strerror, which improves the log messages and debug-ability. However, there are
some potential issues with the way it is getting used. Please note - there are
no changes being proposed to the underlying logging framework.
Current approach (approach 1):
Define message_ids for each log message (except Trace and Debug) and associate
both id and string with a msg_id macro
Replace all calls to gf_log with gf_msg passing in the message_id for the
message. This message_id will be printed as part of the log message.
Document each log string with details of what caused it/how to fix it.
Issues:
1. Code readability - It becomes difficult to figure out what the following is
actually printing and can cause issues with incorrect params being passed or
params being passed in the wrong order:
gf_msg ("dht", GF_LOG_ERROR, 0, dht_msg_23, param1, param2, param3);
2.Code Redundancy -multiple messages for the same thing differing in small
details can potentially use up a large chunk of allocated ids as well as making
it difficult for end users - they will need to search for multiple string
formats/msgids as they could all refer to more or less the same thing. For
example:
dht_msg_1 123, "Failed to get cached subvol for %s"
dht_msg_2 124, "Failed to get cached subvol for %s on %s"
3. Documentation redundancy -
The proposed format for documenting these messages is as follows:
Msg ID
Message format string
Cause
Recommended action
This could potentially lead to documentation like:
Msg ID : 123
Message format string : Failed to get cached subvol for <path>
Cause : The subvolume might not be reachable etc etc
Recommended action : Check network connection etc etc
Msg ID : 124
Message format string : Failed to get cached subvol for <path> on
<path2>
Cause : The subvolume might not be reachable etc etc
Recommended action : Check network connection etc etc
The end user now has to search for multiple msgids and string formats to find
all instances of this error.
NOTE: It may be possible to consolidate all these strings into a single one,
say, "Failed to get cached subvol for %s on %s" and mandate that it be
used in all calls which are currently using variations of the string. However,
this might not be possible in all scenarios - some params might not be available
or might not be meaningful in a particular case or a developer might want to
provide additional info in a particular scenario.
Proposed approach (approach 2):
Define meaningful macros for message_ids for a class of message (except Trace
and Debug) without associating them to a message string. For example
#define DHT_CACHED_SUBVOL_GET_FAILED 123
#define DHT_MEM_ALLOC_FAILED 124
Replace all calls to gf_log with gf_msg but pass in the msg id and string
separately. The string is defined by the developer based on an agreed upon
format.
Define a log message format policy that all developers need to follow. This will
need to be enforced by reviews. For example, we could mandate that all log
messages must start with the name of the file on which the operation is
performed and end with the strerror if it exists.This can also include rules as
to sentence structure and wording - whether to use "failed",
"unable to", "could not" etc.
Consolidate existing messages and reword them if necessary to make them more
meaningful. If a single message will work in multiple instances, use that one
everywhere.
Add your documentation writer as a reviewer for all patches. S/he will be
responsible for ensuring that all newly introduced log messages are meaningful,
consistent and follow the agreed upon format.
Devs will define new message classes ids as and when required.
Ideally, common message classes like dict-set-failed or memory-alloc-failed
should be defined in a common file and included by others - no point having each
component define a memory_alloc_failed id.
With the proposed approach:
#define DHT_CACHED_SUBVOL_GET_FAILED 123
#define DHT_HASHED_SUBVOL_GET_FAILED 124
Calls would then look like:
gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED,
"Failed to get cached subvolume for path %s", param1);
...
gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED,
"Failed to get cached subvolume for path %s on %s", param1, param2);
Documentation would be as follows:
Msg ID : 123
Description : Failed to get the cached subvolume for the specified path
Cause : The subvolume might not be reachable etc etc
Recommended action : Check network connection etc etc
Admins could just search for [MSGID 123] and find all instances of where an
operation failed to get a cached sub volume.
Issues raised with proposed approach:
1. Internationalization: Having the strings in a single file is required to make
L10N easy.
While i18n is very important for user tools, utils etc, log messages are usually
targeted at developers and sys admins who usually know English. Plus it seems
unlikely that log messages will be localized in the near future. However, the
document describing the msgid can be localized so the msg id mapping information
can still be used.
2. Having the strings in a header file makes it easier to change the format
later.
This is a valid point. However, IMHO, the code readability is more important
especially in the case where we pass arguments to the format string.
3. Having a string defined in a single header file can make it easier for a dev
to reuse it if necessary
I would suggest searching on the message id instead and copy the string from
elsewhere if it suits his purpose as those will already have been reviewed by
the doc writer.
Regards,
Nithya
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dht-diskusage_1.c
Type: text/x-c++src
Size: 11964 bytes
Desc: not available
URL:
<http://supercolony.gluster.org/pipermail/gluster-users/attachments/20140430/13451125/attachment.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dht-messages_1.h
Type: text/x-chdr
Size: 21336 bytes
Desc: not available
URL:
<http://supercolony.gluster.org/pipermail/gluster-users/attachments/20140430/13451125/attachment-0001.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dht-diskusage_2.c
Type: text/x-c++src
Size: 12207 bytes
Desc: not available
URL:
<http://supercolony.gluster.org/pipermail/gluster-users/attachments/20140430/13451125/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dht-message-ids_2.h
Type: text/x-chdr
Size: 9767 bytes
Desc: not available
URL:
<http://supercolony.gluster.org/pipermail/gluster-users/attachments/20140430/13451125/attachment-0003.bin>
Joe Julian
2014-Apr-30 13:34 UTC
[Gluster-users] [Gluster-devel] GlusterFS and the logging framework
>From my perspective as someone who supports GlusterFS on IRC and frequently has to read logs in order to determine what went wrong, I like this proposal.On April 30, 2014 12:06:26 AM PDT, Nithya Balachandran <nbalacha at redhat.com> wrote:>Hi, > >I have attached some DHT files to demonstrate the 2 logging approaches. >(*_1 is the original approach, *_2 is the proposed approach).I >personally think the 2 approach leads to better code readability and >propose that we follow approach 2. Please let me know of any concerns >with this. > > >To consolidate all the points raised in the earlier discussions: > > >What are we trying to solve? >Improving gluster logs to make end user debugging easier by providing a >sufficient information and a consistent logging mechanism and message >format . > >The new logging framework already logs the function name and line, >msgid and strerror, which improves the log messages and debug-ability. >However, there are some potential issues with the way it is getting >used. Please note - there are no changes being proposed to the >underlying logging framework. > > >Current approach (approach 1): > >Define message_ids for each log message (except Trace and Debug) and >associate both id and string with a msg_id macro >Replace all calls to gf_log with gf_msg passing in the message_id for >the message. This message_id will be printed as part of the log >message. >Document each log string with details of what caused it/how to fix it. > > > >Issues: >1. Code readability - It becomes difficult to figure out what the >following is actually printing and can cause issues with incorrect >params being passed or params being passed in the wrong order: >gf_msg ("dht", GF_LOG_ERROR, 0, dht_msg_23, param1, param2, param3); > >2.Code Redundancy -multiple messages for the same thing differing in >small details can potentially use up a large chunk of allocated ids as >well as making it difficult for end users - they will need to search >for multiple string formats/msgids as they could all refer to more or >less the same thing. For example: > >dht_msg_1 123, "Failed to get cached subvol for %s" >dht_msg_2 124, "Failed to get cached subvol for %s on %s" > > > >3. Documentation redundancy - > >The proposed format for documenting these messages is as follows: > >Msg ID >Message format string >Cause >Recommended action > >This could potentially lead to documentation like: > >Msg ID : 123 >Message format string : Failed to get cached subvol for <path> >Cause : The subvolume might not be reachable etc etc >Recommended action : Check network connection etc etc > >Msg ID : 124 >Message format string : Failed to get cached subvol for <path> on ><path2> >Cause : The subvolume might not be reachable etc etc >Recommended action : Check network connection etc etc > >The end user now has to search for multiple msgids and string formats >to find all instances of this error. > >NOTE: It may be possible to consolidate all these strings into a single >one, say, "Failed to get cached subvol for %s on %s" and mandate that >it be used in all calls which are currently using variations of the >string. However, this might not be possible in all scenarios - some >params might not be available or might not be meaningful in a >particular case or a developer might want to provide additional info in >a particular scenario. > > > >Proposed approach (approach 2): >Define meaningful macros for message_ids for a class of message (except >Trace and Debug) without associating them to a message string. For >example >#define DHT_CACHED_SUBVOL_GET_FAILED 123 >#define DHT_MEM_ALLOC_FAILED 124 > > >Replace all calls to gf_log with gf_msg but pass in the msg id and >string separately. The string is defined by the developer based on an >agreed upon format. > >Define a log message format policy that all developers need to follow. >This will need to be enforced by reviews. For example, we could mandate >that all log messages must start with the name of the file on which the >operation is performed and end with the strerror if it exists.This can >also include rules as to sentence structure and wording - whether to >use "failed", "unable to", "could not" etc. > >Consolidate existing messages and reword them if necessary to make them >more meaningful. If a single message will work in multiple instances, >use that one everywhere. > >Add your documentation writer as a reviewer for all patches. S/he will >be responsible for ensuring that all newly introduced log messages are >meaningful, consistent and follow the agreed upon format. > >Devs will define new message classes ids as and when required. > >Ideally, common message classes like dict-set-failed or >memory-alloc-failed should be defined in a common file and included by >others - no point having each component define a memory_alloc_failed >id. > >With the proposed approach: > >#define DHT_CACHED_SUBVOL_GET_FAILED 123 >#define DHT_HASHED_SUBVOL_GET_FAILED 124 > >Calls would then look like: > >gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED, "Failed to >get cached subvolume for path %s", param1); >... >gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED, "Failed to >get cached subvolume for path %s on %s", param1, param2); > > >Documentation would be as follows: > >Msg ID : 123 >Description : Failed to get the cached subvolume for the specified path >Cause : The subvolume might not be reachable etc etc >Recommended action : Check network connection etc etc > >Admins could just search for [MSGID 123] and find all instances of >where an operation failed to get a cached sub volume. > >Issues raised with proposed approach: > >1. Internationalization: Having the strings in a single file is >required to make L10N easy. >While i18n is very important for user tools, utils etc, log messages >are usually targeted at developers and sys admins who usually know >English. Plus it seems unlikely that log messages will be localized in >the near future. However, the document describing the msgid can be >localized so the msg id mapping information can still be used. > >2. Having the strings in a header file makes it easier to change the >format later. >This is a valid point. However, IMHO, the code readability is more >important especially in the case where we pass arguments to the format >string. > >3. Having a string defined in a single header file can make it easier >for a dev to reuse it if necessary >I would suggest searching on the message id instead and copy the string >from elsewhere if it suits his purpose as those will already have been >reviewed by the doc writer. > > >Regards, >Nithya > >------------------------------------------------------------------------ > >_______________________________________________ >Gluster-devel mailing list >Gluster-devel at gluster.org >http://supercolony.gluster.org/mailman/listinfo/gluster-devel-- Sent from my Android device with K-9 Mail. Please excuse my brevity. -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://supercolony.gluster.org/pipermail/gluster-users/attachments/20140430/757d2224/attachment.html>
Anand Subramanian
2014-Apr-30 14:07 UTC
[Gluster-users] [Gluster-devel] GlusterFS and the logging framework
Thanks for the detailed explanation Nithya. Is it possible that multiple reasons maybe attached to the same message_id and log-string? In that case I think its good to have a provision for embedding a "rc" in the gf_msg ie. a reason code. Then the documentation can also contain the reason codes; each rc specifying a slightly varying or different reason. That will avoid allocating a completely new id for a new message which is necessary due to a very slight change in behavior warranting only a very subtle change in the description. If its not clear please let me know. Can try and provide an example... Anand On 04/30/2014 12:36 PM, Nithya Balachandran wrote:> Hi, > > I have attached some DHT files to demonstrate the 2 logging approaches. (*_1 is the original approach, *_2 is the proposed approach).I personally think the 2 approach leads to better code readability and propose that we follow approach 2. Please let me know of any concerns with this. > > > To consolidate all the points raised in the earlier discussions: > > > What are we trying to solve? > Improving gluster logs to make end user debugging easier by providing a sufficient information and a consistent logging mechanism and message format . > > The new logging framework already logs the function name and line, msgid and strerror, which improves the log messages and debug-ability. However, there are some potential issues with the way it is getting used. Please note - there are no changes being proposed to the underlying logging framework. > > > Current approach (approach 1): > > Define message_ids for each log message (except Trace and Debug) and associate both id and string with a msg_id macro > Replace all calls to gf_log with gf_msg passing in the message_id for the message. This message_id will be printed as part of the log message. > Document each log string with details of what caused it/how to fix it. > > > > Issues: > 1. Code readability - It becomes difficult to figure out what the following is actually printing and can cause issues with incorrect params being passed or params being passed in the wrong order: > gf_msg ("dht", GF_LOG_ERROR, 0, dht_msg_23, param1, param2, param3); > > 2.Code Redundancy -multiple messages for the same thing differing in small details can potentially use up a large chunk of allocated ids as well as making it difficult for end users - they will need to search for multiple string formats/msgids as they could all refer to more or less the same thing. For example: > > dht_msg_1 123, "Failed to get cached subvol for %s" > dht_msg_2 124, "Failed to get cached subvol for %s on %s" > > > > 3. Documentation redundancy - > > The proposed format for documenting these messages is as follows: > > Msg ID > Message format string > Cause > Recommended action > > This could potentially lead to documentation like: > > Msg ID : 123 > Message format string : Failed to get cached subvol for <path> > Cause : The subvolume might not be reachable etc etc > Recommended action : Check network connection etc etc > > Msg ID : 124 > Message format string : Failed to get cached subvol for <path> on <path2> > Cause : The subvolume might not be reachable etc etc > Recommended action : Check network connection etc etc > > The end user now has to search for multiple msgids and string formats to find all instances of this error. > > NOTE: It may be possible to consolidate all these strings into a single one, say, "Failed to get cached subvol for %s on %s" and mandate that it be used in all calls which are currently using variations of the string. However, this might not be possible in all scenarios - some params might not be available or might not be meaningful in a particular case or a developer might want to provide additional info in a particular scenario. > > > > Proposed approach (approach 2): > Define meaningful macros for message_ids for a class of message (except Trace and Debug) without associating them to a message string. For example > #define DHT_CACHED_SUBVOL_GET_FAILED 123 > #define DHT_MEM_ALLOC_FAILED 124 > > > Replace all calls to gf_log with gf_msg but pass in the msg id and string separately. The string is defined by the developer based on an agreed upon format. > > Define a log message format policy that all developers need to follow. This will need to be enforced by reviews. For example, we could mandate that all log messages must start with the name of the file on which the operation is performed and end with the strerror if it exists.This can also include rules as to sentence structure and wording - whether to use "failed", "unable to", "could not" etc. > > Consolidate existing messages and reword them if necessary to make them more meaningful. If a single message will work in multiple instances, use that one everywhere. > > Add your documentation writer as a reviewer for all patches. S/he will be responsible for ensuring that all newly introduced log messages are meaningful, consistent and follow the agreed upon format. > > Devs will define new message classes ids as and when required. > > Ideally, common message classes like dict-set-failed or memory-alloc-failed should be defined in a common file and included by others - no point having each component define a memory_alloc_failed id. > > With the proposed approach: > > #define DHT_CACHED_SUBVOL_GET_FAILED 123 > #define DHT_HASHED_SUBVOL_GET_FAILED 124 > > Calls would then look like: > > gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED, "Failed to get cached subvolume for path %s", param1); > ... > gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED, "Failed to get cached subvolume for path %s on %s", param1, param2); > > > Documentation would be as follows: > > Msg ID : 123 > Description : Failed to get the cached subvolume for the specified path > Cause : The subvolume might not be reachable etc etc > Recommended action : Check network connection etc etc > > Admins could just search for [MSGID 123] and find all instances of where an operation failed to get a cached sub volume. > > Issues raised with proposed approach: > > 1. Internationalization: Having the strings in a single file is required to make L10N easy. > While i18n is very important for user tools, utils etc, log messages are usually targeted at developers and sys admins who usually know English. Plus it seems unlikely that log messages will be localized in the near future. However, the document describing the msgid can be localized so the msg id mapping information can still be used. > > 2. Having the strings in a header file makes it easier to change the format later. > This is a valid point. However, IMHO, the code readability is more important especially in the case where we pass arguments to the format string. > > 3. Having a string defined in a single header file can make it easier for a dev to reuse it if necessary > I would suggest searching on the message id instead and copy the string from elsewhere if it suits his purpose as those will already have been reviewed by the doc writer. > > > Regards, > Nithya > > > _______________________________________________ > Gluster-devel mailing list > Gluster-devel at gluster.org > http://supercolony.gluster.org/mailman/listinfo/gluster-devel-------------- next part -------------- An HTML attachment was scrubbed... URL: <http://supercolony.gluster.org/pipermail/gluster-users/attachments/20140430/d065a53c/attachment.html>
Dan Lambright
2014-Apr-30 22:37 UTC
[Gluster-users] [Gluster-devel] GlusterFS and the logging framework
Hello,
In a previous job, an engineer in our storage group modified our I/O stack logs
in a manner similar to your proposal #1 (except he did not tell anyone, and did
it for DEBUG messages as well as ERRORS and WARNINGS, over the weekend).
Developers came to work Monday and found over a thousand log message strings had
been buried in a new header file, and any new logs required a new message id,
along with a new string entry in the header file.
This did render the code harder to read. The ensuing uproar closely mirrored the
arguments (1) and (2) you listed. Logs are like comments. If you move them out
of the source, the code is harder to follow. And you probably wan't fewer
message IDs than comments.
The developer retracted his work. After some debate, his V2 solution resembled
your "approach #2". Developers were once again free to use plain text
strings directly in logs, but the notion of "classes" (message ID) was
kept. We allowed multiple text strings to be used against a single class, and
any new classes went in a master header file. The "debug" message ID
class was a general purpose bucket and what most coders used day to day.
So basically, your email sounded very familiar to me and I think your proposal
#2 is on the right track.
Dan
----- Original Message -----
From: "Nithya Balachandran" <nbalacha at redhat.com>
To: gluster-devel at gluster.org
Cc: "gluster-users" <gluster-users at gluster.org>
Sent: Wednesday, April 30, 2014 3:06:26 AM
Subject: [Gluster-devel] GlusterFS and the logging framework
Hi,
I have attached some DHT files to demonstrate the 2 logging approaches. (*_1 is
the original approach, *_2 is the proposed approach).I personally think the 2
approach leads to better code readability and propose that we follow approach 2.
Please let me know of any concerns with this.
To consolidate all the points raised in the earlier discussions:
What are we trying to solve?
Improving gluster logs to make end user debugging easier by providing a
sufficient information and a consistent logging mechanism and message format .
The new logging framework already logs the function name and line, msgid and
strerror, which improves the log messages and debug-ability. However, there are
some potential issues with the way it is getting used. Please note - there are
no changes being proposed to the underlying logging framework.
Current approach (approach 1):
Define message_ids for each log message (except Trace and Debug) and associate
both id and string with a msg_id macro
Replace all calls to gf_log with gf_msg passing in the message_id for the
message. This message_id will be printed as part of the log message.
Document each log string with details of what caused it/how to fix it.
Issues:
1. Code readability - It becomes difficult to figure out what the following is
actually printing and can cause issues with incorrect params being passed or
params being passed in the wrong order:
gf_msg ("dht", GF_LOG_ERROR, 0, dht_msg_23, param1, param2, param3);
2.Code Redundancy -multiple messages for the same thing differing in small
details can potentially use up a large chunk of allocated ids as well as making
it difficult for end users - they will need to search for multiple string
formats/msgids as they could all refer to more or less the same thing. For
example:
dht_msg_1 123, "Failed to get cached subvol for %s"
dht_msg_2 124, "Failed to get cached subvol for %s on %s"
3. Documentation redundancy -
The proposed format for documenting these messages is as follows:
Msg ID
Message format string
Cause
Recommended action
This could potentially lead to documentation like:
Msg ID : 123
Message format string : Failed to get cached subvol for <path>
Cause : The subvolume might not be reachable etc etc
Recommended action : Check network connection etc etc
Msg ID : 124
Message format string : Failed to get cached subvol for <path> on
<path2>
Cause : The subvolume might not be reachable etc etc
Recommended action : Check network connection etc etc
The end user now has to search for multiple msgids and string formats to find
all instances of this error.
NOTE: It may be possible to consolidate all these strings into a single one,
say, "Failed to get cached subvol for %s on %s" and mandate that it be
used in all calls which are currently using variations of the string. However,
this might not be possible in all scenarios - some params might not be available
or might not be meaningful in a particular case or a developer might want to
provide additional info in a particular scenario.
Proposed approach (approach 2):
Define meaningful macros for message_ids for a class of message (except Trace
and Debug) without associating them to a message string. For example
#define DHT_CACHED_SUBVOL_GET_FAILED 123
#define DHT_MEM_ALLOC_FAILED 124
Replace all calls to gf_log with gf_msg but pass in the msg id and string
separately. The string is defined by the developer based on an agreed upon
format.
Define a log message format policy that all developers need to follow. This will
need to be enforced by reviews. For example, we could mandate that all log
messages must start with the name of the file on which the operation is
performed and end with the strerror if it exists.This can also include rules as
to sentence structure and wording - whether to use "failed",
"unable to", "could not" etc.
Consolidate existing messages and reword them if necessary to make them more
meaningful. If a single message will work in multiple instances, use that one
everywhere.
Add your documentation writer as a reviewer for all patches. S/he will be
responsible for ensuring that all newly introduced log messages are meaningful,
consistent and follow the agreed upon format.
Devs will define new message classes ids as and when required.
Ideally, common message classes like dict-set-failed or memory-alloc-failed
should be defined in a common file and included by others - no point having each
component define a memory_alloc_failed id.
With the proposed approach:
#define DHT_CACHED_SUBVOL_GET_FAILED 123
#define DHT_HASHED_SUBVOL_GET_FAILED 124
Calls would then look like:
gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED,
"Failed to get cached subvolume for path %s", param1);
...
gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED,
"Failed to get cached subvolume for path %s on %s", param1, param2);
Documentation would be as follows:
Msg ID : 123
Description : Failed to get the cached subvolume for the specified path
Cause : The subvolume might not be reachable etc etc
Recommended action : Check network connection etc etc
Admins could just search for [MSGID 123] and find all instances of where an
operation failed to get a cached sub volume.
Issues raised with proposed approach:
1. Internationalization: Having the strings in a single file is required to make
L10N easy.
While i18n is very important for user tools, utils etc, log messages are usually
targeted at developers and sys admins who usually know English. Plus it seems
unlikely that log messages will be localized in the near future. However, the
document describing the msgid can be localized so the msg id mapping information
can still be used.
2. Having the strings in a header file makes it easier to change the format
later.
This is a valid point. However, IMHO, the code readability is more important
especially in the case where we pass arguments to the format string.
3. Having a string defined in a single header file can make it easier for a dev
to reuse it if necessary
I would suggest searching on the message id instead and copy the string from
elsewhere if it suits his purpose as those will already have been reviewed by
the doc writer.
Regards,
Nithya
_______________________________________________
Gluster-devel mailing list
Gluster-devel at gluster.org
http://supercolony.gluster.org/mailman/listinfo/gluster-devel
Vijay Bellur
2014-May-01 08:01 UTC
[Gluster-users] [Gluster-devel] GlusterFS and the logging framework
On 05/01/2014 04:07 AM, Dan Lambright wrote:> Hello, > > In a previous job, an engineer in our storage group modified our I/O stack logs in a manner similar to your proposal #1 (except he did not tell anyone, and did it for DEBUG messages as well as ERRORS and WARNINGS, over the weekend). Developers came to work Monday and found over a thousand log message strings had been buried in a new header file, and any new logs required a new message id, along with a new string entry in the header file. > > This did render the code harder to read. The ensuing uproar closely mirrored the arguments (1) and (2) you listed. Logs are like comments. If you move them out of the source, the code is harder to follow. And you probably wan't fewer message IDs than comments. > > The developer retracted his work. After some debate, his V2 solution resembled your "approach #2". Developers were once again free to use plain text strings directly in logs, but the notion of "classes" (message ID) was kept. We allowed multiple text strings to be used against a single class, and any new classes went in a master header file. The "debug" message ID class was a general purpose bucket and what most coders used day to day. > > So basically, your email sounded very familiar to me and I think your proposal #2 is on the right track. >+1. Proposal #2 seems to be better IMO. Thanks, Vijay
Nithya Balachandran
2014-May-02 03:53 UTC
[Gluster-users] [Gluster-devel] GlusterFS and the logging framework
Hi Anand, The gf_msg function currently takes the errno if it is available and includes the error message as part of the log message. However, the errno might not be available in all scenarios. If you mean a gluster specific rc, that is currently not available though it was considered. Our current plan is to ensure all log messages are reviewed by doc to ensure they use a consistent format and provide all the information necessary. It would definitely be helpful if we could define gluster specific error codes and assign msg strings to them similar to the strerror approach. However, even those do not take inputs IIRC - it just provides a high level description of what the error code means. While including the rc would help differentiate the messages and reduce the msg-ids, it does not help the code readability IMO. Hope that helps. Regards, Nithya ----- Original Message ----- From: "Anand Subramanian" <ansubram at redhat.com> To: "Nithya Balachandran" <nbalacha at redhat.com> Cc: gluster-devel at gluster.org, "gluster-users" <gluster-users at gluster.org> Sent: Wednesday, 30 April, 2014 7:37:14 PM Subject: Re: [Gluster-devel] GlusterFS and the logging framework Thanks for the detailed explanation Nithya. Is it possible that multiple reasons maybe attached to the same message_id and log-string? In that case I think its good to have a provision for embedding a "rc" in the gf_msg ie. a reason code. Then the documentation can also contain the reason codes; each rc specifying a slightly varying or different reason. That will avoid allocating a completely new id for a new message which is necessary due to a very slight change in behavior warranting only a very subtle change in the description. If its not clear please let me know. Can try and provide an example... Anand On 04/30/2014 12:36 PM, Nithya Balachandran wrote:> Hi, > > I have attached some DHT files to demonstrate the 2 logging approaches. (*_1 is the original approach, *_2 is the proposed approach).I personally think the 2 approach leads to better code readability and propose that we follow approach 2. Please let me know of any concerns with this. > > > To consolidate all the points raised in the earlier discussions: > > > What are we trying to solve? > Improving gluster logs to make end user debugging easier by providing a sufficient information and a consistent logging mechanism and message format . > > The new logging framework already logs the function name and line, msgid and strerror, which improves the log messages and debug-ability. However, there are some potential issues with the way it is getting used. Please note - there are no changes being proposed to the underlying logging framework. > > > Current approach (approach 1): > > Define message_ids for each log message (except Trace and Debug) and associate both id and string with a msg_id macro > Replace all calls to gf_log with gf_msg passing in the message_id for the message. This message_id will be printed as part of the log message. > Document each log string with details of what caused it/how to fix it. > > > > Issues: > 1. Code readability - It becomes difficult to figure out what the following is actually printing and can cause issues with incorrect params being passed or params being passed in the wrong order: > gf_msg ("dht", GF_LOG_ERROR, 0, dht_msg_23, param1, param2, param3); > > 2.Code Redundancy -multiple messages for the same thing differing in small details can potentially use up a large chunk of allocated ids as well as making it difficult for end users - they will need to search for multiple string formats/msgids as they could all refer to more or less the same thing. For example: > > dht_msg_1 123, "Failed to get cached subvol for %s" > dht_msg_2 124, "Failed to get cached subvol for %s on %s" > > > > 3. Documentation redundancy - > > The proposed format for documenting these messages is as follows: > > Msg ID > Message format string > Cause > Recommended action > > This could potentially lead to documentation like: > > Msg ID : 123 > Message format string : Failed to get cached subvol for <path> > Cause : The subvolume might not be reachable etc etc > Recommended action : Check network connection etc etc > > Msg ID : 124 > Message format string : Failed to get cached subvol for <path> on <path2> > Cause : The subvolume might not be reachable etc etc > Recommended action : Check network connection etc etc > > The end user now has to search for multiple msgids and string formats to find all instances of this error. > > NOTE: It may be possible to consolidate all these strings into a single one, say, "Failed to get cached subvol for %s on %s" and mandate that it be used in all calls which are currently using variations of the string. However, this might not be possible in all scenarios - some params might not be available or might not be meaningful in a particular case or a developer might want to provide additional info in a particular scenario. > > > > Proposed approach (approach 2): > Define meaningful macros for message_ids for a class of message (except Trace and Debug) without associating them to a message string. For example > #define DHT_CACHED_SUBVOL_GET_FAILED 123 > #define DHT_MEM_ALLOC_FAILED 124 > > > Replace all calls to gf_log with gf_msg but pass in the msg id and string separately. The string is defined by the developer based on an agreed upon format. > > Define a log message format policy that all developers need to follow. This will need to be enforced by reviews. For example, we could mandate that all log messages must start with the name of the file on which the operation is performed and end with the strerror if it exists.This can also include rules as to sentence structure and wording - whether to use "failed", "unable to", "could not" etc. > > Consolidate existing messages and reword them if necessary to make them more meaningful. If a single message will work in multiple instances, use that one everywhere. > > Add your documentation writer as a reviewer for all patches. S/he will be responsible for ensuring that all newly introduced log messages are meaningful, consistent and follow the agreed upon format. > > Devs will define new message classes ids as and when required. > > Ideally, common message classes like dict-set-failed or memory-alloc-failed should be defined in a common file and included by others - no point having each component define a memory_alloc_failed id. > > With the proposed approach: > > #define DHT_CACHED_SUBVOL_GET_FAILED 123 > #define DHT_HASHED_SUBVOL_GET_FAILED 124 > > Calls would then look like: > > gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED, "Failed to get cached subvolume for path %s", param1); > ... > gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED, "Failed to get cached subvolume for path %s on %s", param1, param2); > > > Documentation would be as follows: > > Msg ID : 123 > Description : Failed to get the cached subvolume for the specified path > Cause : The subvolume might not be reachable etc etc > Recommended action : Check network connection etc etc > > Admins could just search for [MSGID 123] and find all instances of where an operation failed to get a cached sub volume. > > Issues raised with proposed approach: > > 1. Internationalization: Having the strings in a single file is required to make L10N easy. > While i18n is very important for user tools, utils etc, log messages are usually targeted at developers and sys admins who usually know English. Plus it seems unlikely that log messages will be localized in the near future. However, the document describing the msgid can be localized so the msg id mapping information can still be used. > > 2. Having the strings in a header file makes it easier to change the format later. > This is a valid point. However, IMHO, the code readability is more important especially in the case where we pass arguments to the format string. > > 3. Having a string defined in a single header file can make it easier for a dev to reuse it if necessary > I would suggest searching on the message id instead and copy the string from elsewhere if it suits his purpose as those will already have been reviewed by the doc writer. > > > Regards, > Nithya > > > _______________________________________________ > Gluster-devel mailing list > Gluster-devel at gluster.org > http://supercolony.gluster.org/mailman/listinfo/gluster-devel
Nithya Balachandran
2014-May-02 04:18 UTC
[Gluster-users] [Gluster-devel] GlusterFS and the logging framework
Thanks Joe. Assuming you like approach#2, please let us know of anything else that you would find helpful in the gluster logs. Thanks, Nithya ----- Original Message ----- From: "Joe Julian" <joe at julianfamily.org> To: "Nithya Balachandran" <nbalacha at redhat.com>, gluster-devel at gluster.org Cc: "gluster-users" <gluster-users at gluster.org> Sent: Wednesday, 30 April, 2014 7:04:14 PM Subject: Re: [Gluster-devel] GlusterFS and the logging framework>From my perspective as someone who supports GlusterFS on IRC and frequently has to read logs in order to determine what went wrong, I like this proposal.On April 30, 2014 12:06:26 AM PDT, Nithya Balachandran <nbalacha at redhat.com> wrote:>Hi, > >I have attached some DHT files to demonstrate the 2 logging approaches. >(*_1 is the original approach, *_2 is the proposed approach).I >personally think the 2 approach leads to better code readability and >propose that we follow approach 2. Please let me know of any concerns >with this. > > >To consolidate all the points raised in the earlier discussions: > > >What are we trying to solve? >Improving gluster logs to make end user debugging easier by providing a >sufficient information and a consistent logging mechanism and message >format . > >The new logging framework already logs the function name and line, >msgid and strerror, which improves the log messages and debug-ability. >However, there are some potential issues with the way it is getting >used. Please note - there are no changes being proposed to the >underlying logging framework. > > >Current approach (approach 1): > >Define message_ids for each log message (except Trace and Debug) and >associate both id and string with a msg_id macro >Replace all calls to gf_log with gf_msg passing in the message_id for >the message. This message_id will be printed as part of the log >message. >Document each log string with details of what caused it/how to fix it. > > > >Issues: >1. Code readability - It becomes difficult to figure out what the >following is actually printing and can cause issues with incorrect >params being passed or params being passed in the wrong order: >gf_msg ("dht", GF_LOG_ERROR, 0, dht_msg_23, param1, param2, param3); > >2.Code Redundancy -multiple messages for the same thing differing in >small details can potentially use up a large chunk of allocated ids as >well as making it difficult for end users - they will need to search >for multiple string formats/msgids as they could all refer to more or >less the same thing. For example: > >dht_msg_1 123, "Failed to get cached subvol for %s" >dht_msg_2 124, "Failed to get cached subvol for %s on %s" > > > >3. Documentation redundancy - > >The proposed format for documenting these messages is as follows: > >Msg ID >Message format string >Cause >Recommended action > >This could potentially lead to documentation like: > >Msg ID : 123 >Message format string : Failed to get cached subvol for <path> >Cause : The subvolume might not be reachable etc etc >Recommended action : Check network connection etc etc > >Msg ID : 124 >Message format string : Failed to get cached subvol for <path> on ><path2> >Cause : The subvolume might not be reachable etc etc >Recommended action : Check network connection etc etc > >The end user now has to search for multiple msgids and string formats >to find all instances of this error. > >NOTE: It may be possible to consolidate all these strings into a single >one, say, "Failed to get cached subvol for %s on %s" and mandate that >it be used in all calls which are currently using variations of the >string. However, this might not be possible in all scenarios - some >params might not be available or might not be meaningful in a >particular case or a developer might want to provide additional info in >a particular scenario. > > > >Proposed approach (approach 2): >Define meaningful macros for message_ids for a class of message (except >Trace and Debug) without associating them to a message string. For >example >#define DHT_CACHED_SUBVOL_GET_FAILED 123 >#define DHT_MEM_ALLOC_FAILED 124 > > >Replace all calls to gf_log with gf_msg but pass in the msg id and >string separately. The string is defined by the developer based on an >agreed upon format. > >Define a log message format policy that all developers need to follow. >This will need to be enforced by reviews. For example, we could mandate >that all log messages must start with the name of the file on which the >operation is performed and end with the strerror if it exists.This can >also include rules as to sentence structure and wording - whether to >use "failed", "unable to", "could not" etc. > >Consolidate existing messages and reword them if necessary to make them >more meaningful. If a single message will work in multiple instances, >use that one everywhere. > >Add your documentation writer as a reviewer for all patches. S/he will >be responsible for ensuring that all newly introduced log messages are >meaningful, consistent and follow the agreed upon format. > >Devs will define new message classes ids as and when required. > >Ideally, common message classes like dict-set-failed or >memory-alloc-failed should be defined in a common file and included by >others - no point having each component define a memory_alloc_failed >id. > >With the proposed approach: > >#define DHT_CACHED_SUBVOL_GET_FAILED 123 >#define DHT_HASHED_SUBVOL_GET_FAILED 124 > >Calls would then look like: > >gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED, "Failed to >get cached subvolume for path %s", param1); >... >gf_msg ("dht", GF_LOG_ERROR, DHT_CACHED_SUBVOL_GET_FAILED, "Failed to >get cached subvolume for path %s on %s", param1, param2); > > >Documentation would be as follows: > >Msg ID : 123 >Description : Failed to get the cached subvolume for the specified path >Cause : The subvolume might not be reachable etc etc >Recommended action : Check network connection etc etc > >Admins could just search for [MSGID 123] and find all instances of >where an operation failed to get a cached sub volume. > >Issues raised with proposed approach: > >1. Internationalization: Having the strings in a single file is >required to make L10N easy. >While i18n is very important for user tools, utils etc, log messages >are usually targeted at developers and sys admins who usually know >English. Plus it seems unlikely that log messages will be localized in >the near future. However, the document describing the msgid can be >localized so the msg id mapping information can still be used. > >2. Having the strings in a header file makes it easier to change the >format later. >This is a valid point. However, IMHO, the code readability is more >important especially in the case where we pass arguments to the format >string. > >3. Having a string defined in a single header file can make it easier >for a dev to reuse it if necessary >I would suggest searching on the message id instead and copy the string >from elsewhere if it suits his purpose as those will already have been >reviewed by the doc writer. > > >Regards, >Nithya > >------------------------------------------------------------------------ > >_______________________________________________ >Gluster-devel mailing list >Gluster-devel at gluster.org >http://supercolony.gluster.org/mailman/listinfo/gluster-devel-- Sent from my Android device with K-9 Mail. Please excuse my brevity.