Re: [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 ansub...@redhat.com To: Nithya Balachandran nbala...@redhat.com Cc: gluster-devel@gluster.org, gluster-users gluster-us...@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
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,
Re: [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 nbala...@redhat.com To: gluster-devel@gluster.org Cc: gluster-users gluster-us...@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
