Bug 1082

Summary: LogComponentEnable() does not provide error handling
Product: ns-3 Reporter: Anirudh <sk.anirudh>
Component: coreAssignee: Mathieu Lacage <mathieu.lacage>
Status: RESOLVED FIXED    
Severity: major CC: ns-bugs, tomh
Priority: P5    
Version: pre-release   
Hardware: All   
OS: All   
Attachments: Patch to add error handling if component name is misspelt in LogComponentEnable()
Patch to trap mispelt component names

Description Anirudh 2011-03-27 08:08:40 EDT
Created attachment 1052 [details]
Patch to add error handling if component name is misspelt in LogComponentEnable()

LogComponentEnable(string ComponentName) which is defined in src/core/model/log.cc in the current ns-3-dev trunk does not provide appropriate error handling when ComponentName is misspelt. 

This can be very misleading because it does not give any indication to the user that the name is misspelt. Instead, it continues running as usual and produces no log output. This could be easily confused with the desired log component not producing any output in the simulation while it is in reality not producing output because ComponentName has been misspelt.

I have attached a patch to fix this. I think it would be useful for this to be integrated in the tree even though it is a very small fix, because logging is an important part of debugging.


Anirudh
Comment 1 Tom Henderson 2011-03-27 15:32:23 EDT
(In reply to comment #0)
> Created attachment 1052 [details]
> Patch to add error handling if component name is misspelt in
> LogComponentEnable()
> 
> LogComponentEnable(string ComponentName) which is defined in
> src/core/model/log.cc in the current ns-3-dev trunk does not provide
> appropriate error handling when ComponentName is misspelt. 
> s not give any indication to the user
> that the name is misspelt. Instead, it continues running as usual and produces
> no log output. This could be easily confused with the desired log component not
> producing any output in the simulation while it is in reality not producing
> output because ComponentName has been misspelt.
> 
> I have attached a patch to fix this. I think it would be useful for this to be
> integrated in the tree even though it is a very small fix, because logging is
> an important part of debugging.
> 
> 

In general, I agree with what you are trying to do.  My concerns here are, first, that FATAL_ERROR seems a bit drastic since this will not result in incorrect program output.  Could you not just use NS_LOG_UNCOND here and achieve the same result?  Second, we want to make sure that the same behavior is provided when the NS_LOG environmental variable is used.  so probably something similar needs to be done to LogComponent::EnvVarCheck ().
Comment 2 Anirudh 2011-03-27 21:22:41 EDT
(In reply to comment #1)
> (In reply to comment #0)
> > Created attachment 1052 [details]
> > Patch to add error handling if component name is misspelt in
> > LogComponentEnable()
> > 
> > LogComponentEnable(string ComponentName) which is defined in
> > src/core/model/log.cc in the current ns-3-dev trunk does not provide
> > appropriate error handling when ComponentName is misspelt. 
> > s not give any indication to the user
> > that the name is misspelt. Instead, it continues running as usual and produces
> > no log output. This could be easily confused with the desired log component not
> > producing any output in the simulation while it is in reality not producing
> > output because ComponentName has been misspelt.
> > 
> > I have attached a patch to fix this. I think it would be useful for this to be
> > integrated in the tree even though it is a very small fix, because logging is
> > an important part of debugging.
> > 
> > 
> 
> In general, I agree with what you are trying to do.  My concerns here are,
> first, that FATAL_ERROR seems a bit drastic since this will not result in
> incorrect program output.  Could you not just use NS_LOG_UNCOND here and
> achieve the same result?  Second, we want to make sure that the same behavior
> is provided when the NS_LOG environmental variable is used.  so probably
> something similar needs to be done to LogComponent::EnvVarCheck ().

Ok. Would it make sense to stall the program then by :
1. Displaying that the desired component name does not exist.
2. Prompting the user for a yes and no as to whether he wants to continue?

I am concerned that using NS_LOG_UNCOND would print an error message out saying
"Component not found." But this line would probably go unnoticed in the midst of a lot of other logging output from the simulator.

Regarding the environmental variable aspect, I 'll fix that in the appropriate function and attach a new patch.
Comment 3 Tom Henderson 2011-03-28 03:50:47 EDT
(In reply to comment #2)
> (In reply to comment #1)
> > (In reply to comment #0)
> > > Created attachment 1052 [details]
> > > Patch to add error handling if component name is misspelt in
> > > LogComponentEnable()
> > > 
> > > LogComponentEnable(string ComponentName) which is defined in
> > > src/core/model/log.cc in the current ns-3-dev trunk does not provide
> > > appropriate error handling when ComponentName is misspelt. 
> > > s not give any indication to the user
> > > that the name is misspelt. Instead, it continues running as usual and produces
> > > no log output. This could be easily confused with the desired log component not
> > > producing any output in the simulation while it is in reality not producing
> > > output because ComponentName has been misspelt.
> > > 
> > > I have attached a patch to fix this. I think it would be useful for this to be
> > > integrated in the tree even though it is a very small fix, because logging is
> > > an important part of debugging.
> > > 
> > > 
> > 
> > In general, I agree with what you are trying to do.  My concerns here are,
> > first, that FATAL_ERROR seems a bit drastic since this will not result in
> > incorrect program output.  Could you not just use NS_LOG_UNCOND here and
> > achieve the same result?  Second, we want to make sure that the same behavior
> > is provided when the NS_LOG environmental variable is used.  so probably
> > something similar needs to be done to LogComponent::EnvVarCheck ().
> 
> Ok. Would it make sense to stall the program then by :
> 1. Displaying that the desired component name does not exist.
> 2. Prompting the user for a yes and no as to whether he wants to continue?
> 
> I am concerned that using NS_LOG_UNCOND would print an error message out saying
> "Component not found." But this line would probably go unnoticed in the midst
> of a lot of other logging output from the simulator.

I think that it is overkill to try to handle this with elaborate mechanisms; I might prefer a fatal error over pausing the program.  

My main concerns are the following:
- try to keep NS_LOG and LogComponentEnable behavior the same
- do not cause errors if a user previously enabled a valid log component but built ns-3 without support for that module.  For instance, export NS_LOG="MyLogComponent" and then later try to run another program that doesn't contain MyLogComponent.  ns-3 is moving to a modular build system now so we must keep in mind that the modules in use may be changing.

I guess we could also consider adding a "pedantic logging" global value that would enforce the fatal error if selected (default off).  That way, we could tell people in the tutorial to set this pedantic bit if they wanted to enforce that LogComponentEnable() was valid.
Comment 4 Anirudh 2011-03-28 06:56:35 EDT
(In reply to comment #3)
> (In reply to comment #2)
> > (In reply to comment #1)
> > > (In reply to comment #0)
> > > > Created attachment 1052 [details]
> > > > Patch to add error handling if component name is misspelt in
> > > > LogComponentEnable()
> > > > 
> > > > LogComponentEnable(string ComponentName) which is defined in
> > > > src/core/model/log.cc in the current ns-3-dev trunk does not provide
> > > > appropriate error handling when ComponentName is misspelt. 
> > > > s not give any indication to the user
> > > > that the name is misspelt. Instead, it continues running as usual and produces
> > > > no log output. This could be easily confused with the desired log component not
> > > > producing any output in the simulation while it is in reality not producing
> > > > output because ComponentName has been misspelt.
> > > > 
> > > > I have attached a patch to fix this. I think it would be useful for this to be
> > > > integrated in the tree even though it is a very small fix, because logging is
> > > > an important part of debugging.
> > > > 
> > > > 
> > > 
> > > In general, I agree with what you are trying to do.  My concerns here are,
> > > first, that FATAL_ERROR seems a bit drastic since this will not result in
> > > incorrect program output.  Could you not just use NS_LOG_UNCOND here and
> > > achieve the same result?  Second, we want to make sure that the same behavior
> > > is provided when the NS_LOG environmental variable is used.  so probably
> > > something similar needs to be done to LogComponent::EnvVarCheck ().
> > 
> > Ok. Would it make sense to stall the program then by :
> > 1. Displaying that the desired component name does not exist.
> > 2. Prompting the user for a yes and no as to whether he wants to continue?
> > 
> > I am concerned that using NS_LOG_UNCOND would print an error message out saying
> > "Component not found." But this line would probably go unnoticed in the midst
> > of a lot of other logging output from the simulator.
> 
> I think that it is overkill to try to handle this with elaborate mechanisms; I
> might prefer a fatal error over pausing the program.  
> 
> My main concerns are the following:
> - try to keep NS_LOG and LogComponentEnable behavior the same
> - do not cause errors if a user previously enabled a valid log component but
> built ns-3 without support for that module.  For instance, export
> NS_LOG="MyLogComponent" and then later try to run another program that doesn't
> contain MyLogComponent.  ns-3 is moving to a modular build system now so we
> must keep in mind that the modules in use may be changing.
> 
> I guess we could also consider adding a "pedantic logging" global value that
> would enforce the fatal error if selected (default off).  That way, we could
> tell people in the tutorial to set this pedantic bit if they wanted to enforce
> that LogComponentEnable() was valid.

Ok,

I understand the first point and the point about pedantic logging. I am not sure I got the second about not causing spurious errors. 

Presently I handle this logging bug by comparing against the set of all log components available at run time. If the user enables logging for a particular module in his program but builds ns without support for that module, how do I detect such a situation? In other words, is there a static list of modules available elsewhere which I can compare a module name against to detect an error in the logging component name. 

Or can I change the error message to say "Either the module does not exist or you have not built ns-3 with support for this module" ?

Regards
Anirudh
Comment 5 Mathieu Lacage 2011-03-30 06:06:59 EDT
I disagree with tom on this one: I see no point in silently allowing an invalid call to LogComponentEnable, and modularity is irrelevant here: NS_FATAL_ERROR seems like an appropriate way to flag this.

However, I do agree with tom that we should make sure that the NS_LOG env var parsing code should behave like LogComponentEnable.
Comment 6 Anirudh 2011-03-31 10:57:26 EDT
(In reply to comment #5)
> I disagree with tom on this one: I see no point in silently allowing an invalid
> call to LogComponentEnable, and modularity is irrelevant here: NS_FATAL_ERROR
> seems like an appropriate way to flag this.
> 
> However, I do agree with tom that we should make sure that the NS_LOG env var
> parsing code should behave like LogComponentEnable.

So, will it suffice if I add the same error checking to the environment variable parsing code too? If yes, I can do the same and upload a patch immediately. 

I am not sure how to address the modularity issue though: as I pointed out, I can't find a way to list out all modules available ( not just those available at run time).


Anirudh
Comment 7 Mathieu Lacage 2011-04-01 03:03:44 EDT
(In reply to comment #6)
> (In reply to comment #5)
> > I disagree with tom on this one: I see no point in silently allowing an invalid
> > call to LogComponentEnable, and modularity is irrelevant here: NS_FATAL_ERROR
> > seems like an appropriate way to flag this.
> > 
> > However, I do agree with tom that we should make sure that the NS_LOG env var
> > parsing code should behave like LogComponentEnable.
> 
> So, will it suffice if I add the same error checking to the environment
> variable parsing code too? If yes, I can do the same and upload a patch
> immediately. 

yes, something like that.

> I am not sure how to address the modularity issue though: as I pointed out, I
> can't find a way to list out all modules available ( not just those available
> at run time).

There is no such static list so, nothing that I can see to fix this issue.
Comment 8 Anirudh 2011-04-01 16:01:32 EDT
(In reply to comment #7)
> (In reply to comment #6)
> > (In reply to comment #5)
> > > I disagree with tom on this one: I see no point in silently allowing an invalid
> > > call to LogComponentEnable, and modularity is irrelevant here: NS_FATAL_ERROR
> > > seems like an appropriate way to flag this.
> > > 
> > > However, I do agree with tom that we should make sure that the NS_LOG env var
> > > parsing code should behave like LogComponentEnable.
> > 
> > So, will it suffice if I add the same error checking to the environment
> > variable parsing code too? If yes, I can do the same and upload a patch
> > immediately. 
> 
> yes, something like that.
> 
> > I am not sure how to address the modularity issue though: as I pointed out, I
> > can't find a way to list out all modules available ( not just those available
> > at run time).
> 
> There is no such static list so, nothing that I can see to fix this issue.

I had a look at EnvVarCheck() which is a member function of the class LogComponent. The component's name is checked against the environmental variable NS_LOG to decide whether to enable it's logging or not. To handle someone misspelling the component name while exporting NS_LOG we need to check NS_LOG against GetComponentList(). This function is straightforward to write, but where would it be called? I am not very familiar with the code structure in ns-3. Is there some initialisation function where this check of NS_LOG can be done?
Comment 9 Mathieu Lacage 2011-07-06 19:04:34 EDT
(In reply to comment #8)
> (In reply to comment #7)
> > (In reply to comment #6)
> > > (In reply to comment #5)
> > > > I disagree with tom on this one: I see no point in silently allowing an invalid
> > > > call to LogComponentEnable, and modularity is irrelevant here: NS_FATAL_ERROR
> > > > seems like an appropriate way to flag this.
> > > > 
> > > > However, I do agree with tom that we should make sure that the NS_LOG env var
> > > > parsing code should behave like LogComponentEnable.
> > > 
> > > So, will it suffice if I add the same error checking to the environment
> > > variable parsing code too? If yes, I can do the same and upload a patch
> > > immediately. 
> > 
> > yes, something like that.
> > 
> > > I am not sure how to address the modularity issue though: as I pointed out, I
> > > can't find a way to list out all modules available ( not just those available
> > > at run time).
> > 
> > There is no such static list so, nothing that I can see to fix this issue.
> 
> I had a look at EnvVarCheck() which is a member function of the class
> LogComponent. The component's name is checked against the environmental
> variable NS_LOG to decide whether to enable it's logging or not. To handle
> someone misspelling the component name while exporting NS_LOG we need to check
> NS_LOG against GetComponentList(). This function is straightforward to write,
> but where would it be called? I am not very familiar with the code structure in
> ns-3. Is there some initialisation function where this check of NS_LOG can be
> done?

No, there is no initialization function. The code was designed to do lazy initialization which is why you never know if you are really done initializing. This is why you can never know the difference between a mis-spelled component name or a not-yet-constructed component. I guess I could be convinced to call a new check function from Simulator::Run or something similar. Ha, we could re-use (ab-use) LogSetTimePrinter which is called from the Simulator code when the Simulator object is created to do the check and FATAL if NS_LOG contains a vname which does not exist.
Comment 10 Anirudh 2011-08-08 20:02:57 EDT
Created attachment 1219 [details]
Patch to trap mispelt component names
Comment 11 Anirudh 2011-08-08 20:05:07 EDT
(In reply to comment #9)
> (In reply to comment #8)
> > (In reply to comment #7)
> > > (In reply to comment #6)
> > > > (In reply to comment #5)
> > > > > I disagree with tom on this one: I see no point in silently allowing an invalid
> > > > > call to LogComponentEnable, and modularity is irrelevant here: NS_FATAL_ERROR
> > > > > seems like an appropriate way to flag this.
> > > > > 
> > > > > However, I do agree with tom that we should make sure that the NS_LOG env var
> > > > > parsing code should behave like LogComponentEnable.
> > > > 
> > > > So, will it suffice if I add the same error checking to the environment
> > > > variable parsing code too? If yes, I can do the same and upload a patch
> > > > immediately. 
> > > 
> > > yes, something like that.
> > > 
> > > > I am not sure how to address the modularity issue though: as I pointed out, I
> > > > can't find a way to list out all modules available ( not just those available
> > > > at run time).
> > > 
> > > There is no such static list so, nothing that I can see to fix this issue.
> > 
> > I had a look at EnvVarCheck() which is a member function of the class
> > LogComponent. The component's name is checked against the environmental
> > variable NS_LOG to decide whether to enable it's logging or not. To handle
> > someone misspelling the component name while exporting NS_LOG we need to check
> > NS_LOG against GetComponentList(). This function is straightforward to write,
> > but where would it be called? I am not very familiar with the code structure in
> > ns-3. Is there some initialisation function where this check of NS_LOG can be
> > done?
> 
> No, there is no initialization function. The code was designed to do lazy
> initialization which is why you never know if you are really done initializing.
> This is why you can never know the difference between a mis-spelled component
> name or a not-yet-constructed component. I guess I could be convinced to call a
> new check function from Simulator::Run or something similar. Ha, we could
> re-use (ab-use) LogSetTimePrinter which is called from the Simulator code when
> the Simulator object is created to do the check and FATAL if NS_LOG contains a
> vname which does not exist.



Hi

I have attached a patch, checking if NS_LOG is well formed. It checks the following:
1. The component name(s) in NS_LOG are registered with ns-3.
2. The log levels are sensible log levels , for instance you can't type "LOG_XYZ" into the env variable.
3. If LogComponentEnable is used instead of the env variable NS_LOG, it checks that as well.

In all these three cases, it throws a fatal error and displays the list of registered components for the user's convenience. I have attached a patch against the latest version of log.cc from the source tree, and have tested this with ns-3.11. 

Please let me know if this is fine, when you have the time to review it and sorry for the delay in sending this.

Anirudh
Comment 12 Anirudh 2011-08-08 20:06:16 EDT
(In reply to comment #11)
> (In reply to comment #9)
> > (In reply to comment #8)
> > > (In reply to comment #7)
> > > > (In reply to comment #6)
> > > > > (In reply to comment #5)
> > > > > > I disagree with tom on this one: I see no point in silently allowing an invalid
> > > > > > call to LogComponentEnable, and modularity is irrelevant here: NS_FATAL_ERROR
> > > > > > seems like an appropriate way to flag this.
> > > > > > 
> > > > > > However, I do agree with tom that we should make sure that the NS_LOG env var
> > > > > > parsing code should behave like LogComponentEnable.
> > > > > 
> > > > > So, will it suffice if I add the same error checking to the environment
> > > > > variable parsing code too? If yes, I can do the same and upload a patch
> > > > > immediately. 
> > > > 
> > > > yes, something like that.
> > > > 
> > > > > I am not sure how to address the modularity issue though: as I pointed out, I
> > > > > can't find a way to list out all modules available ( not just those available
> > > > > at run time).
> > > > 
> > > > There is no such static list so, nothing that I can see to fix this issue.
> > > 
> > > I had a look at EnvVarCheck() which is a member function of the class
> > > LogComponent. The component's name is checked against the environmental
> > > variable NS_LOG to decide whether to enable it's logging or not. To handle
> > > someone misspelling the component name while exporting NS_LOG we need to check
> > > NS_LOG against GetComponentList(). This function is straightforward to write,
> > > but where would it be called? I am not very familiar with the code structure in
> > > ns-3. Is there some initialisation function where this check of NS_LOG can be
> > > done?
> > 
> > No, there is no initialization function. The code was designed to do lazy
> > initialization which is why you never know if you are really done initializing.
> > This is why you can never know the difference between a mis-spelled component
> > name or a not-yet-constructed component. I guess I could be convinced to call a
> > new check function from Simulator::Run or something similar. Ha, we could
> > re-use (ab-use) LogSetTimePrinter which is called from the Simulator code when
> > the Simulator object is created to do the check and FATAL if NS_LOG contains a
> > vname which does not exist.
> 
> 
> 
> Hi
> 
> I have attached a patch, checking if NS_LOG is well formed. It checks the
> following:
> 1. The component name(s) in NS_LOG are registered with ns-3.
> 2. The log levels are sensible log levels , for instance you can't type
> "LOG_XYZ" into the env variable.
> 3. If LogComponentEnable is used instead of the env variable NS_LOG, it checks
> that as well.
> 
> In all these three cases, it throws a fatal error and displays the list of
> registered components for the user's convenience. I have attached a patch
> against the latest version of log.cc from the source tree, and have tested this
> with ns-3.11. 
> 
> Please let me know if this is fine, when you have the time to review it and
> sorry for the delay in sending this.
> 
> Anirudh

I am sorry for the spam. But I attached the patch without saving my comments and hence three posts. Please let me know if the patch is ok.

Anirudh
Comment 13 Mathieu Lacage 2011-08-10 12:24:07 EDT
I applied a modified version of your patch:

1) tabs !, trailing whitespace... Not good
2) not coding-style compliant if/then/else indentation. The correct way:
if ()
  {
    // stuff
  }
else
  {
    // stuff
  }
3) {} are not optional in if/then/else statements. i.e., no single-line statements
4) NS_FATAL_ERROR ("foo" << bar); is must more readable than doing the string formatting outside of the NS_FATAL_ERROR
5) the following:
if (foo)
  {
    // do stuff
  }
else
  {
    NS_ASSERT (1 == 0);
  }

  i. NS_ASSERT (1 == 0); -> NS_ASSERT (false);
  ii. but all of that can be rewritten much more easily to NS_ASSERT (foo);
6) missing test for '*' in set of level log levels: was seen as an invalid log level...
7) you obviously did not check the code with ./test.py because all tests crash due to a missing test for strlen(envVar) == 0 in CheckEnvironmentVariables 
8) doing the check from SetTimer clearly deserved at least a comment inside the code.

I would advise you to review the patch I finally committed on http://code.nsnam.org/ns-3-dev/rev/1e965c4c084b

changeset: 1e965c4c084b
Comment 14 Anirudh 2011-08-10 12:44:33 EDT
(In reply to comment #13)
> I applied a modified version of your patch:
> 
> 1) tabs !, trailing whitespace... Not good
> 2) not coding-style compliant if/then/else indentation. The correct way:
> if ()
>   {
>     // stuff
>   }
> else
>   {
>     // stuff
>   }
> 3) {} are not optional in if/then/else statements. i.e., no single-line
> statements
> 4) NS_FATAL_ERROR ("foo" << bar); is must more readable than doing the string
> formatting outside of the NS_FATAL_ERROR
> 5) the following:
> if (foo)
>   {
>     // do stuff
>   }
> else
>   {
>     NS_ASSERT (1 == 0);
>   }
> 
>   i. NS_ASSERT (1 == 0); -> NS_ASSERT (false);
>   ii. but all of that can be rewritten much more easily to NS_ASSERT (foo);
> 6) missing test for '*' in set of level log levels: was seen as an invalid log
> level...
> 7) you obviously did not check the code with ./test.py because all tests crash
> due to a missing test for strlen(envVar) == 0 in CheckEnvironmentVariables 
> 8) doing the check from SetTimer clearly deserved at least a comment inside the
> code.
> 
> I would advise you to review the patch I finally committed on
> http://code.nsnam.org/ns-3-dev/rev/1e965c4c084b
> 
> changeset: 1e965c4c084b
Hi

I took a look at the patch in the context of the comments you made. It looks good to me. Also, sorry for not confirming to the coding/formatting guidelines, will be more careful with that next time around.

Anirudh