Bugzilla – Bug 1531
Crash when using NS_LOG in destructors of static objects
Last modified: 2012-12-09 00:45:14 EST
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 ()
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.
Patch for bug 1496 introduced the std::map Mathieu is referring to: Commit 9c0cc3997ece http://code.nsnam.org/ns-3-dev/rev/9c0cc3997ece
Commit 7353 [09fccf6195ea] changed the include guard.
(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.
Created attachment 1478 [details] Revised patch
(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.
revised patch pushed in changeset: 065a297f6c9d