Bug 1531

Summary: Crash when using NS_LOG in destructors of static objects
Product: ns-3 Reporter: Peter Barnes <pdbarnes>
Component: coreAssignee: Mathieu Lacage <mathieu.lacage>
Status: RESOLVED FIXED    
Severity: normal CC: ns-bugs, tomh
Priority: P5    
Version: ns-3-dev   
Hardware: All   
OS: All   
See Also: https://www.nsnam.org/bugzilla/show_bug.cgi?id=1496
Attachments: Patch that leaves new'ed memory undeleted.
Revised patch

Description Peter Barnes 2012-11-15 02:38:56 UTC 
Created attachment 1468 [details]
Patch that leaves new'ed memory undeleted.

Use of NS_LOG_x in destructors called during cleanup can cause a crash.

This is because of static (de)initialization order in LogComponent::GetLevelLabel().

The patch attached fixes this issue, but leaves new'ed memory undeleted, a valgrind issue.

Steps to reproduce:
Apply the Time::SetResolution patch:
http://codereview.appspot.com/6821106/
(This logs construction/destruction of Time objects until Time::SetResolution is called.)

Configure debug, and run, with logging on Time:
$ NS_LOG="Time=all|prefix_all" ./wf --run scratch-simulator

This end of the output will look like:

Scratch Simulator
Time:TimeUnset(): [LOGIC] [133] removing  0x10b8dd218
Time:TimeUnset(): [LOGIC] [132] removing  0x10b8dd220
Time:TimeUnset(): [LOGIC] [131] removing  0x10b8dd1d8
Time:TimeUnset(): [LOGIC] [130] removing  0x10b8dd1e0
Time:TimeUnset(): [LOGIC] [129] removing  0x10b8dd148
Time:TimeUnset(): [LOGIC] [128] removing  0x10b8dd150
Time:TimeUnset(): [LOGIC] [127] removing  0x10cd18a98
Time:TimeUnset(): [LOGIC] [126] removing  0x10e274f70
Time:TimeUnset(): Command ['/Users/barnes26/Code/netsim/ns3/repos/time2/build/scratch/scratch-simulator'] terminated with signal SIGSEGV. Run it under a debugger

The first line quoted above "Scratch Simulator" is the only user code in the main program.  Everything after that is cleaning up.

The backtrace is:
#0  0x0000000103cc53ea in std::less<ns3::LogLevel>::operator() ()
#1  0x0000000103cc5cd1 in std::_Rb_tree<ns3::LogLevel, std::pair<ns3::LogLevel const, std::string>, std::_Select1st<std::pair<ns3::LogLevel const, std::string> >, std::less<ns3::LogLevel>, std::allocator<std::pair<ns3::LogLevel const, std::string> > >::lower_bound ()
#2  0x0000000103cc5d6f in std::map<ns3::LogLevel, std::string, std::less<ns3::LogLevel>, std::allocator<std::pair<ns3::LogLevel const, std::string> > >::lower_bound ()
#3  0x0000000103cc73b4 in std::map<ns3::LogLevel, std::string, std::less<ns3::LogLevel>, std::allocator<std::pair<ns3::LogLevel const, std::string> > >::operator[] ()
#4  0x0000000103cc456f in ns3::LogComponent::GetLevelLabel ()
#5  0x0000000103c8159e in ns3::Time::TimeUnset ()
#6  0x0000000100002996 in ns3::Time::~Time (this=0x104708540) at nstime.h:178
#7  0x0000000103c8695e in ns3::TimeValue::~TimeValue ()
#8  0x0000000100033c6a in ns3::DefaultDeleter<ns3::AttributeValue>::Delete ()
#9  0x0000000100033caf in ns3::SimpleRefCount<ns3::AttributeValue, ns3::empty, ns3::DefaultDeleter<ns3::AttributeValue> >::Unref ()
#10 0x0000000103847b6b in ns3::Ptr<ns3::AttributeValue const>::~Ptr ()
#11 0x000000010384839f in ns3::TypeId::AttributeInformation::~AttributeInformation ()
#12 0x0000000103cdd088 in std::_Destroy<ns3::TypeId::AttributeInformation> ()
#13 0x0000000103cdd0ae in std::__destroy_aux<ns3::TypeId::AttributeInformation*> ()
#14 0x0000000103cdd10f in std::_Destroy<ns3::TypeId::AttributeInformation*> ()
#15 0x0000000103cdd147 in std::_Destroy<ns3::TypeId::AttributeInformation*, ns3::TypeId::AttributeInformation> ()
#16 0x0000000103cdd193 in std::vector<ns3::TypeId::AttributeInformation, std::allocator<ns3::TypeId::AttributeInformation> >::~vector ()
#17 0x0000000103cc8d1d in (anonymous namespace)::IidManager::IidInformation::~IidInformation ()
#18 0x0000000103cc8f68 in std::_Destroy<(anonymous namespace)::IidManager::IidInformation> ()
#19 0x0000000103cc8f8e in std::__destroy_aux<(anonymous namespace)::IidManager::IidInformation*> ()
#20 0x0000000103cc8fef in std::_Destroy<(anonymous namespace)::IidManager::IidInformation*> ()
#21 0x0000000103cc9027 in std::_Destroy<(anonymous namespace)::IidManager::IidInformation*, (anonymous namespace)::IidManager::IidInformation> ()
#22 0x0000000103cc9073 in std::vector<(anonymous namespace)::IidManager::IidInformation, std::allocator<(anonymous namespace)::IidManager::IidInformation> >::~vector ()
#23 0x0000000103cc914c in (anonymous namespace)::IidManager::~IidManager ()
#24 0x0000000103cc917b in __tcf_0 ()
#25 0x00007fff8e264307 in __cxa_finalize ()
#26 0x00007fff8e265f57 in exit ()
#27 0x00007fff894637e8 in start ()

Note stack frame 4 is the last ns3 function:
#4  0x0000000103cc456f in ns3::LogComponent::GetLevelLabel ()
Comment 1 Mathieu Lacage 2012-11-26 04:21:36 UTC 
At first, I thought that this sounded like a good idea but I reviewed the code and some log.h/cc changes that are recent but which I failed to look at earlier.

1) earlier patches change #ifdef __LOG_H__ to LOG_H. oops. I was about to ask : "what is the likelyhood that someone has a LOG_H macro defined ?". It is sufficiently high that it should be at least NS3_LOG_H instead. (which, I think, is the ns-3-sanctified-style anyway)

2) Are you suggesting that we make the code leak a std::map upon each call to GetLevelLabel ? I might be really just sleepy/soaked to the bones on a rainy monday morning but this sounds like a bad idea (tm). GetLevelLabel can be called by pretty much any logging statement, depending on how you have setup your logging output, right ? 

3) Why is GetLevelLabel not coded with a switch/case statement ? a std::map that contains 5 hardcoded items ? Unless there is a serious reason for that, we could trivially change that code to use a set of if/then/else or switch/case statements, close the bug, and get back to business.
Comment 2 Peter Barnes 2012-11-27 22:50:26 UTC 
Patch for bug 1496 introduced the std::map Mathieu is referring to:

Commit 9c0cc3997ece
http://code.nsnam.org/ns-3-dev/rev/9c0cc3997ece
Comment 3 Peter Barnes 2012-11-28 22:22:19 UTC 
Commit 7353 [09fccf6195ea] changed the include guard.
Comment 4 Peter Barnes 2012-11-28 22:33:31 UTC 
(In reply to comment #1)
> 1) earlier patches change #ifdef __LOG_H__ to LOG_H. oops. I was about to
Changed to NS3_LOG_H.
(We have 740 include guards; only 24 use NS_* NS2_* NS3_* or NSC_*)

> 2) Are you suggesting that we make the code leak a std::map upon each call
> to GetLevelLabel ? I might be really just sleepy/soaked to the bones on a
> rainy monday morning but this sounds like a bad idea (tm). GetLevelLabel can
Yes, it is a bad idea (tm).

> 3) Why is GetLevelLabel not coded with a switch/case statement ? a std::map
Thankyou!  This is much nicer.

Revised patch attached.
Comment 5 Peter Barnes 2012-11-28 22:34:25 UTC 
Created attachment 1478 [details]
Revised patch
Comment 6 Mathieu Lacage 2012-11-29 03:21:30 UTC 
(In reply to comment #5)
> Created attachment 1478 [details]
> Revised patch

It looks like the patch has some other changes to the logic of which levels to log (or maybe it is just code shuffling, I can't tell without reviewing this more carefully) but I trust you have tested this so, it is good for commit on my side.

thanks for this quick turnaround time.
Comment 7 Tom Henderson 2012-12-09 00:45:14 UTC 
revised patch pushed in changeset: 065a297f6c9d