Opened 9 years ago

Closed 9 years ago

#559 closed defect (fixed)

lib/log test crashes with --enable-static-link

Reported by: jinmei Owned by: stephen
Priority: high Milestone: R-Team-Sprint-20110222
Component: logging Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity:
Sub-Project: Feature Depending on Ticket:
Estimated Difficulty: 0.0 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

On my environment (MacOS 10.6, g++ and clang++) if I build BIND 10
with --enable-static-link lib/log tests fail with logger_support_test
being crashed. After looking into it a bit closer, I found this is
actually a more serious issue of the liblog itself.

This is the backtrace:

#0  0x00007fff89143405 in std::string::_Rep::_M_dispose ()
#1  0x00007fff89144124 in std::string::assign ()
#2  0x0000000100000fda in std::string::_M_rep () at /Users/jinmei/src/isc/git/bind10/src/lib/log/root_logger_name.h:38
#3  0x0000000100000fda in ~basic_string [inlined] () at logger_support_test.cc:493
#4  ~basic_string [inlined] () at /Users/jinmei/src/isc/git/bind10/src/lib/log/root_logger_name.h:493
#5  0x0000000100000fda in __static_initialization_and_destruction_0 (__initialize_p=<value temporarily unavailable, due to optimizations>, __priority=<value temporarily unavailable, due to optimizations>) at logger_support_test.cc:38
#6  0x00007fff5fc0d500 in __dyld__ZN16ImageLoaderMachO18doModInitFunctionsERKN11ImageLoader11LinkContextE ()
#7  0x00007fff5fc0bcec in __dyld__ZN11ImageLoader23recursiveInitializationERKNS_11LinkContextEj ()
#8  0x00007fff5fc0bda6 in __dyld__ZN11ImageLoader15runInitializersERKNS_11LinkContextE ()
#9  0x00007fff5fc0210e in __dyld__ZN4dyld24initializeMainExecutableEv ()
#10 0x00007fff5fc06981 in __dyld__ZN4dyld5_mainEPK12macho_headermiPPKcS5_S5_ ()
#11 0x00007fff5fc016d2 in __dyld__ZN13dyldbootstrap5startEPK12macho_headeriPPKcl ()
#12 0x00007fff5fc01052 in __dyld__dyld_start ()

Fram #5 is at this line of logger_support_test.cc:

RootLoggerName root("alpha");

Apparently this is a typical symptom of the static initialization
order fiasco. In fact, if I moved the definition of "root" inside
main(), it at least stopped crashing. But the test still kept
failing.

So I looked into some other parts of lib/log, and found that it relies
too much on statically initialized (non const) objects. From a quick
look, the "logger" variable defined in logger_support.cc has this
problem. The namespace level initialization in logger.cc and
root_logger_name.cc seems to be dangerous, too.

I suggest revisiting overall initialization in lib/log so that it will
be more robust. Since this bug can (potentially) make the application
crash, I'd categorize it as "critical".

I'm giving this ticket to Stephen.

BTW, I happen to notice messagedef.h uses an unnamed namespace. It's
generally a discouraged practice as it can easily break the "one
definition rule".

Subtickets

Change History (3)

comment:1 Changed 9 years ago by stephen

  • Milestone changed from R-Team-Task-Backlog to R-Team-Sprint-20110208

comment:2 Changed 9 years ago by stephen

Apparently this is a typical symptom of the static initialization
order fiasco. In fact, if I moved the definition of "root" inside
main(), it at least stopped crashing.

Doh! I was so focused on avoid initialization problems between classes I'd written that I overlooked the ones within classes. In the case of RootLoggerName, the singleton variable holding the name has been moved inside a static function (so is instantiated when that function is called).

But the test still kept failing.

This was the more tricky one. The idea is that each library/subsystem has its own message file and that the message text is pulled in simply by ensuring that the object code produced by the .cc file was included in the image (i.e. without the need to call any run-time initialization). With dynamic linking, the module is in the library and appears to be brought in regardless. But with static linking, as there is no reference to symbols in the module, it does not get included in the final image.

To get round this I've included in the header file generated by the message compiler an "extern" reference to the MessageInitializer object. As this may well get optimised away, the header also declares a "MessageInstantiator" object, passing the address of the MessageInitializer to its constructor. The MessageInstantiator is a dummy object, comprising a constructor (in an external file to avoid it being optimised away) that does nothing. But this should create the reference to the MessageInitializer object needed to ensure that the message text gets included in the image.

So I looked into some other parts of lib/log, and found that it relies
too much on statically initialized (non const) objects. From a quick
look, the "logger" variable defined in logger_support.cc has this
problem. The namespace level initialization in logger.cc and
root_logger_name.cc seems to be dangerous, too.

There are three places where this occurs:

a) Declaration of the root logger name. This just sets a name for use in the logging system; providing this is set before the first call to (any) logger is made, it doesn't matter where it is declared. Now that the initialization has been corrected, this can be declared externally or in main(), whatever seems best.
b) Declaration of the message identifiers. You're right, I missed "const". (See below for more discussion on message identifiers.)
c) Declaration of the loggers. At the risk of premature optimisation, I wanted to minimise the overhead of call to a logging function that does not result in output. As a logger needs to be created at some point:

  • Putting it in the method making the call incurs the overhead of instantiation and destruction each time the method is called.
  • Declaring the logger as part of the class (so instantiating it once for an instance of the class) does not seem right, as the logger is not logically part of the class. Also, we may want logging in objects where thousands are created and destroyed.
  • Declaring the logger as a static variable in the method. Certainly possible, but we could end up with many declarations of the same logger in a file.
  • Declaring it as external - a single declaration in a file.

The logger is written so that it can be declared in any of these contexts. To avoid initialization problems (and the interaction with the (possible) static initialization of the root logger name), the logger uses "pimpl" but defers instantiating the implementation class until the first time any of its methods is called.

I suggest revisiting overall initialization in lib/log so that it will
be more robust. Since this bug can (potentially) make the application
crash, I'd categorize it as "critical".

Done

BTW, I happen to notice messagedef.h uses an unnamed namespace. It's
generally a discouraged practice as it can easily break the "one
definition rule".

The message file can now contain a $NAMESPACE directive to set the namespace in which the symbols are created, and they are declared as "static" in it.

This brings up the case of message identifiers. Mainly because of the requirement to be able to replace the message text at run-time, message identifiers are text. I originally declared them as strings, owing to the possibility that someone might return a message ID as a status return code and then compare it against other message IDs. However, as you brought to notice, this could run the risk of a static initialization fiacso if someone tried to access a message ID in a statically declared object.

To avoid this, the code was changed slightly and message identifiers are now declared as "const char*". This still gives the advantage of text (and avoids the need to run constructors on potentially thousands of message IDs at program start-up time), but now introduces a different problem; "a ==b" is only guaranteed to work if both IDs are obtained from the same module. If two modules each include the message header file, it is possible that two instances of the string are created, each ending up at a separate address.

To get round this, message_types.h includes a function "equalsMessageID()" to perform equality checks. But a different way occurs to me: declare the symbols as external, i.e. in the .h file declare "extern const char* symbol;" and in the .cc file define the symbol "const char* symbol = "value";". This:

  • solves the problems of symbol equality - all symbols of the same name will have the same value.
  • allows the removal of the "MessageInstantiator" object - the .cc file will always be included in the link in order to resolve the symbol definitions.

However, this solution does break encapsulation by generating many external references in each module that defines message IDs, and for that reason I'm hesitant of it.

Review
The set of changes addressing these points is included on ticket #558, and that should be the one used handle the source code review.

comment:3 Changed 9 years ago by stephen

  • Resolution set to fixed
  • Status changed from new to closed

Modifications (and estimate) included in the changes applied for ticket #558 (which is why the estimate has been set to 0.)

Note: See TracTickets for help on using tickets.