Log4cxx
  1. Log4cxx
  2. LOGCXX-111

make Logger cache a LoggerRepositoryPtr instead of a "blind" pointer

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 0.10.0
    • Fix Version/s: 0.10.0
    • Component/s: None
    • Labels:
      None

      Description

      Hi

      The following patch (the biggest from the series) changes the codes so that Logger caches a LoggerRepositoryPtr instead of a LoggerRepository* otherwise the cached pointer may get "delete"ed before it's last use (as proved by valgrind and SIGSEGV). This patch fixes the first crash I got with log4cxx when trying to log from a destructor of a static object.

        Activity

        Hide
        Curt Arnold added a comment -

        Committed changes in r 371612 that check if the repository is non-null before calling one of its methods. This and the changes to objectptr.h in LOGCXX-112 should result in Loggers that are created after the destruction of the default logger repository to be ineffectual, but at least they shouldn't crash.

        I suspect that there are other improvements to the code that should make log4cxx more stable when logging in static destructors. However full capabilities will require that users understand the initialization and destruction rules, so that log4cxx isn't partially destructed at the time that you want to do logging requests. I'm closing this issue, if there are other scenarios and test cases that you want to add, please report them as a different issue.

        Show
        Curt Arnold added a comment - Committed changes in r 371612 that check if the repository is non-null before calling one of its methods. This and the changes to objectptr.h in LOGCXX-112 should result in Loggers that are created after the destruction of the default logger repository to be ineffectual, but at least they shouldn't crash. I suspect that there are other improvements to the code that should make log4cxx more stable when logging in static destructors. However full capabilities will require that users understand the initialization and destruction rules, so that log4cxx isn't partially destructed at the time that you want to do logging requests. I'm closing this issue, if there are other scenarios and test cases that you want to add, please report them as a different issue.
        Hide
        Mihai Rusu added a comment -

        Forgot about what you lastasked me. I have tried to create a separate test case but failed to reproduce the behaivour

        Show
        Mihai Rusu added a comment - Forgot about what you lastasked me. I have tried to create a separate test case but failed to reproduce the behaivour
        Hide
        Mihai Rusu added a comment -

        Yes I was wrong. I think I confused the destruction "no-guarantee" issue with the construction one (which indeed exists, that is you don't have any standard guarantee of the order of object initialization of global data across different translation units). You do have a guarantee of the order of the destructors called it seems.

        Then I don't know, maybe it's a bug of g++ or their interpretation of the standard that doesn't do this. Because clearly (as valgrind reports) without my patch a destructor of a static object of mine when trying to log is making a call trace that ends up accessing a LoggerRepository dangling pointer which as valgrind shows has been delete-ed from the DefaultLoggerRepository destructor (which is a static object).

        The "dummyLogger" trick I can try but I need to declare it in every translation unit that declares static objects that contain LoggerPtr in them (although most of my static objects are in main()'s translation unit but not all... yeah it sounds like a bad design but I don't have THAT many static objects ).

        Show
        Mihai Rusu added a comment - Yes I was wrong. I think I confused the destruction "no-guarantee" issue with the construction one (which indeed exists, that is you don't have any standard guarantee of the order of object initialization of global data across different translation units). You do have a guarantee of the order of the destructors called it seems. Then I don't know, maybe it's a bug of g++ or their interpretation of the standard that doesn't do this. Because clearly (as valgrind reports) without my patch a destructor of a static object of mine when trying to log is making a call trace that ends up accessing a LoggerRepository dangling pointer which as valgrind shows has been delete-ed from the DefaultLoggerRepository destructor (which is a static object). The "dummyLogger" trick I can try but I need to declare it in every translation unit that declares static objects that contain LoggerPtr in them (although most of my static objects are in main()'s translation unit but not all... yeah it sounds like a bad design but I don't have THAT many static objects ).
        Hide
        Curt Arnold added a comment -

        The following seems to be a guarantee of the order of destructors by my reading.

        Section 3.6.3-1

        1- Destructors (class.dtor) for initialized objects of static storage duration (declared at block scope or at namespace scope) are called as a result of returning from main and as a result of calling exit (lib.support.start.term). These objects are destroyed in the reverse order of the completion of their constructor or of the completion of their dynamic initialization. If an object is initialized statically, the object is destroyed in the same order as if the object was dynamically initialized. For an object of array or class type, all subobjects of that object are destroyed before any local object with static storage duration initialized during the construction of the subobjects is destroyed.

        http://www.atnf.csiro.au/computing/software/sol2docs/mr/READMEs/c++.html#forder also suggests that others see the C++ standard as specifying an order for destruction cross compilation units (reverse of the unspecified initialization order).

        I was mentioning that since it might provide you with a means of controlling destruction sufficient to avoid your current crashes until we find a permanent solution.

        Yes, log4cxx does try to emulate log4j semantics.

        I've been "homeless" for a couple of weeks and don't have all the resources (books and time) that I would typically have and this type of problem would require. I'm going to be moving into my new place on Monday and should be able to go deeper on the issue.

        Many months ago, we had to address static object initialization. log4cxx-0.9.7 would crash a lot on constructor logging since the relative order of initialization was unspecified. That was resolved by eliminating non-local static members. The flip-side wasn't considered at that time. It took a while to understand the nuances of the problem and I expect this will take some time to work through the issues. The ideas in your patch may eventually be adopted, however it changes the API more than I'd like to commit without a thorough review of the issue.

        It would be great if you could attach some trivial examples that result in crashes while logging in destructors. Please specify what compiler, OS, etc, were used.

        Show
        Curt Arnold added a comment - The following seems to be a guarantee of the order of destructors by my reading. Section 3.6.3-1 1- Destructors (class.dtor) for initialized objects of static storage duration (declared at block scope or at namespace scope) are called as a result of returning from main and as a result of calling exit (lib.support.start.term). These objects are destroyed in the reverse order of the completion of their constructor or of the completion of their dynamic initialization. If an object is initialized statically, the object is destroyed in the same order as if the object was dynamically initialized. For an object of array or class type, all subobjects of that object are destroyed before any local object with static storage duration initialized during the construction of the subobjects is destroyed. http://www.atnf.csiro.au/computing/software/sol2docs/mr/READMEs/c++.html#forder also suggests that others see the C++ standard as specifying an order for destruction cross compilation units (reverse of the unspecified initialization order). I was mentioning that since it might provide you with a means of controlling destruction sufficient to avoid your current crashes until we find a permanent solution. Yes, log4cxx does try to emulate log4j semantics. I've been "homeless" for a couple of weeks and don't have all the resources (books and time) that I would typically have and this type of problem would require. I'm going to be moving into my new place on Monday and should be able to go deeper on the issue. Many months ago, we had to address static object initialization. log4cxx-0.9.7 would crash a lot on constructor logging since the relative order of initialization was unspecified. That was resolved by eliminating non-local static members. The flip-side wasn't considered at that time. It took a while to understand the nuances of the problem and I expect this will take some time to work through the issues. The ideas in your patch may eventually be adopted, however it changes the API more than I'd like to commit without a thorough review of the issue. It would be great if you could attach some trivial examples that result in crashes while logging in destructors. Please specify what compiler, OS, etc, were used.
        Hide
        Mihai Rusu added a comment -

        Hmm, this issue tracker does not seem to have a feature to directly quote on the text so I'll try to emulate it.

        "Unlike the encoders and decoders in LOGCXX-112, the repo can't be effectively recovered after its destructed."
        Agreed (I don't know log4cxx that well but to me it seems to be a complex structure so it makes sense).

        "The repo will need to be destructed at some point unless you want to leak a lot of resources and then others would complain."
        Of course, we need to make sure it is destructed at some point.

        "The only reliable option is to make it easy to force initialization of all essential log4cxx static resources (like the default repo) to occur before the initialization of the static object that logs during its destructor.

        Since objects are supposed to be destructed in reverse order of their construction (your mileage may vary based on your compiler) and you can control the relative initialization order within a compile unit by the placement, you may be able to force the defer the destruction of the repo by forcing its creation to occur before the constructor of your static object."

        This I do not fully agree. Acording to my reading and understanding of the ISO C++ features while the compiler HAS to guarantee an exact order to construct and destruct objects from a single translation unit (ie in the same translation unit the static objects are constructed in the order of appearance and are destructed in the reversed order obviously) there is absolutely no guarantee to the order of constructors/destructors across different translation units. Considering that here we are talking about my codes (log4cxx user) and the log4cxx codes they are cleary at least 2 separate translation units. This means that the copiler and the C++ standard offer no guarantee that:
        1. the constructors of the static objects of log4cxx are called before any of the static objects of my codes (this you might end up using uninitlized resources if in the constructors you use log4cxx)
        2. the destructors of the static objects of log4cxx are called AFTER all the destructors of my static objects are finished (ie I might end up using invalid data)

        AFAIK, to be able to manage this dependency issue (because it's a dependency issue, some static objects lifetime depends on other static object's lifetime) usually the user has to emply reference counters. The same problem for example is addressed with std::cin/cout/cerr/clog because they are 4 static iostream objects that need to be "constructed" before any of their users and also need to be destroyed after all of their users have finished. The solution employed usually with iostreams is like this: there is a header file included by all cin/cout/clog/cerr users, this header file declares something like "static iostreamreference reference;" meanging that all cin/cout/clog/cerr users get a iostreamreference object created in their own translation unit (as it's "static" in the header file) and this iostreamreference object in the constructor all it does is initilize the cin/cout/cerr/clog streams if not already and increment the usage count, and in the destructor decrements the user count and destroys them if count reaches 0.

        Because I have seen that log4cxx already makes heavy usage of reference counted smart pointers (probably because it somewhat tries to emulate the log4j aproach) I thought to myself that just adding a reference count for the object used by the Logger's whould be enough and acording to my tests it solves the crash I got. Theoretically any object that is using the services of another object which lifetime is decoupled from the user (ie it is NOT created directly by the user and it is NOT destroyed directly by the user) needs to cache the pointers/references of the used object with a reference count mechanism through a Singleton-like interface to make sure the used object is created already when we need it and that is destroyed only after we don't need it anymore.

        "Say if you have:

        Foo myStaticFoo;

        You could change it to:

        LoggerPtr dummyLogger(Logger::getLogger("com.example.SomeLogger"));
        Foo myStaticFoo;

        which would force initialization of log4cxx to occur before the initialization of the static Foo. "

        My users are just classes that embed a LoggerPtr object member initilized with log4cxx::getLogger from the constructor. As such there are already reference counter mechanisms (provided by LoggerPtr) that make sure that the Logger used by my object's constructors is alive as long as my object lives. And my experience proved that it indeed works nicely. The only problem is that there is a "blind shared pointer" to a static LoggerRepository object (Hierarcy) in each Logger, that might get destructed before every Logger gets destructed (because we have no guarantee that the static object destructors from the translation unit in log4cxx that included the static Hierarchy object are called after the destructors of my objects which might log using LoggerPtr that point to a Logger that uses the cached LoggerRepository pointer). As such, the example you provided shouldnt solve my problem either.

        Hope I explained better now

        Show
        Mihai Rusu added a comment - Hmm, this issue tracker does not seem to have a feature to directly quote on the text so I'll try to emulate it. "Unlike the encoders and decoders in LOGCXX-112 , the repo can't be effectively recovered after its destructed." Agreed (I don't know log4cxx that well but to me it seems to be a complex structure so it makes sense). "The repo will need to be destructed at some point unless you want to leak a lot of resources and then others would complain." Of course, we need to make sure it is destructed at some point. "The only reliable option is to make it easy to force initialization of all essential log4cxx static resources (like the default repo) to occur before the initialization of the static object that logs during its destructor. Since objects are supposed to be destructed in reverse order of their construction (your mileage may vary based on your compiler) and you can control the relative initialization order within a compile unit by the placement, you may be able to force the defer the destruction of the repo by forcing its creation to occur before the constructor of your static object." This I do not fully agree. Acording to my reading and understanding of the ISO C++ features while the compiler HAS to guarantee an exact order to construct and destruct objects from a single translation unit (ie in the same translation unit the static objects are constructed in the order of appearance and are destructed in the reversed order obviously) there is absolutely no guarantee to the order of constructors/destructors across different translation units. Considering that here we are talking about my codes (log4cxx user) and the log4cxx codes they are cleary at least 2 separate translation units. This means that the copiler and the C++ standard offer no guarantee that: 1. the constructors of the static objects of log4cxx are called before any of the static objects of my codes (this you might end up using uninitlized resources if in the constructors you use log4cxx) 2. the destructors of the static objects of log4cxx are called AFTER all the destructors of my static objects are finished (ie I might end up using invalid data) AFAIK, to be able to manage this dependency issue (because it's a dependency issue, some static objects lifetime depends on other static object's lifetime) usually the user has to emply reference counters. The same problem for example is addressed with std::cin/cout/cerr/clog because they are 4 static iostream objects that need to be "constructed" before any of their users and also need to be destroyed after all of their users have finished. The solution employed usually with iostreams is like this: there is a header file included by all cin/cout/clog/cerr users, this header file declares something like "static iostreamreference reference;" meanging that all cin/cout/clog/cerr users get a iostreamreference object created in their own translation unit (as it's "static" in the header file) and this iostreamreference object in the constructor all it does is initilize the cin/cout/cerr/clog streams if not already and increment the usage count, and in the destructor decrements the user count and destroys them if count reaches 0. Because I have seen that log4cxx already makes heavy usage of reference counted smart pointers (probably because it somewhat tries to emulate the log4j aproach) I thought to myself that just adding a reference count for the object used by the Logger's whould be enough and acording to my tests it solves the crash I got. Theoretically any object that is using the services of another object which lifetime is decoupled from the user (ie it is NOT created directly by the user and it is NOT destroyed directly by the user) needs to cache the pointers/references of the used object with a reference count mechanism through a Singleton-like interface to make sure the used object is created already when we need it and that is destroyed only after we don't need it anymore. "Say if you have: Foo myStaticFoo; You could change it to: LoggerPtr dummyLogger(Logger::getLogger("com.example.SomeLogger")); Foo myStaticFoo; which would force initialization of log4cxx to occur before the initialization of the static Foo. " My users are just classes that embed a LoggerPtr object member initilized with log4cxx::getLogger from the constructor. As such there are already reference counter mechanisms (provided by LoggerPtr) that make sure that the Logger used by my object's constructors is alive as long as my object lives. And my experience proved that it indeed works nicely. The only problem is that there is a "blind shared pointer" to a static LoggerRepository object (Hierarcy) in each Logger, that might get destructed before every Logger gets destructed (because we have no guarantee that the static object destructors from the translation unit in log4cxx that included the static Hierarchy object are called after the destructors of my objects which might log using LoggerPtr that point to a Logger that uses the cached LoggerRepository pointer). As such, the example you provided shouldnt solve my problem either. Hope I explained better now
        Hide
        Curt Arnold added a comment -

        I'm going to need to understand this one better. Unlike the encoders and decoders in LOGCXX-112, the repo can't be effectively recovered after its destructed. The repo will need to be destructed at some point unless you want to leak a lot of resources and then others would complain. The only reliable option is to make it easy to force initialization of all essential log4cxx static resources (like the default repo) to occur before the initialization of the static object that logs during its destructor.

        Since objects are supposed to be destructed in reverse order of their construction (your mileage may vary based on your compiler) and you can control the relative initialization order within a compile unit by the placement, you may be able to force the defer the destruction of the repo by forcing its creation to occur before the constructor of your static object.

        Say if you have:

        Foo myStaticFoo;

        You could change it to:

        LoggerPtr dummyLogger(Logger::getLogger("com.example.SomeLogger"));
        Foo myStaticFoo;

        which would force initialization of log4cxx to occur before the initialization of the static Foo.

        Show
        Curt Arnold added a comment - I'm going to need to understand this one better. Unlike the encoders and decoders in LOGCXX-112 , the repo can't be effectively recovered after its destructed. The repo will need to be destructed at some point unless you want to leak a lot of resources and then others would complain. The only reliable option is to make it easy to force initialization of all essential log4cxx static resources (like the default repo) to occur before the initialization of the static object that logs during its destructor. Since objects are supposed to be destructed in reverse order of their construction (your mileage may vary based on your compiler) and you can control the relative initialization order within a compile unit by the placement, you may be able to force the defer the destruction of the repo by forcing its creation to occur before the constructor of your static object. Say if you have: Foo myStaticFoo; You could change it to: LoggerPtr dummyLogger(Logger::getLogger("com.example.SomeLogger")); Foo myStaticFoo; which would force initialization of log4cxx to occur before the initialization of the static Foo.

          People

          • Assignee:
            Curt Arnold
            Reporter:
            Mihai Rusu
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development