BIND 10 #1966: logger formatter does too much in the destructor

[BIND 10 Development]

#1966: logger formatter does too much in the destructor
-------------------------------------+-------------------------------------
                   Reporter:         |                 Owner:
  jinmei                             |                Status:  new
                       Type:         |             Milestone:  Next-Sprint-
  defect                             |  Proposed
                   Priority:         |            Resolution:
  medium                             |             Sensitive:  0
                  Component:         |           Sub-Project:  Core
  logging                            |  Estimated Difficulty:  0
                   Keywords:         |           Total Hours:  0
            Defect Severity:  N/A    |
Feature Depending on Ticket:         |
        Add Hours to Ticket:  0      |
                  Internal?:  0      |
-------------------------------------+-------------------------------------

Comment (by jinmei):

 Replying to [comment:4 vorner]:
 > This will require both less convenient use and expensive change of all
 our logging code. And I don't see the benefit.

 > Generally, throwing from destructor can cause trouble. But it's because
 C++
 > doesn't really handle the case when two exceptions are being thrown at
 once
 > (because there are problems with explicit memory deallocation and
 generally
 > exceptions and explicit deallocation cause trouble). But I don't think
 there
 > can be two exceptions at once in this case.

 I'm not sure if we are talking about the same things, but in my
 understanding there are two specific reasons why we should avoid
 throwing from a destructor:

 1. If the destructor in question is called during stack unwinding due
   to another exception thrown, the nested exception immediately
   terminates the program with no other loophole.
 2. Destructors are often responsible for critical resource release
   operations.  If a destructor throws in the middle of it, we can
   never complete the cleanup.

 Maybe you meant problem 1, and didn't think it happened for the Formatter
 class?  Actually, unless I miss something it can happen for it; and,
 problem 2 can clearly happen for it.

 As for #1, consider the following expression:

 {{{#!cpp
     // where thisOneThrows is expected to return a std::string but can
 throw.
     Formatter(INFO, message, this).arg(thisOneThrows());
 }}}

 If `thisOneThrows()` throws, the `Formatters` destructor will be
 called in the middle of stack unwinding due to that exception.  Or,
 arg() itself is relatively a complicated method, internally calling
 boost and other standard library functions, could throw, too.

 Problem 2 should be more obvious from the implementation:

 {{{#!cpp
     ~ Formatter() {
         if (logger_) {
             checkExcessPlaceholders(message_, ++nextPlaceholder_);
             logger_->output(severity_, *message_);
             delete message_;
         }
     }
 }}}

 Think about what will happen for `message_` when the destructor throws
 before `delete` (if you are about to insist we could make it safe by
 tweaking the implementation, read the next paragraph first).

 But, actually, I was a bit surprised that we needed to have such a
 discussion in the first place.  IMO, it's too fragile to rely on the
 specific behavior of a class to selectively allow such a generally
 (severely) discouraged practice as throwing from a destructor; as
 we've seen, humans can easily make errors in the behavior analysis,
 and even if the analysis is correct at one point in time, a small
 future change can easily break it and trigger a surprised behavior.
 So, to me, this is something we must always meet without even
 considering whether it can be an exceptional case to the general
 convention.  We in fact experienced one small surprise that was
 addressed in #1964.  One might want to argue it's a special case of
 intentionally triggered test scenario, but to me it looks like a tip
 of the iceberg.

 As for convenience, I admit it would surely be less convenient, but I
 don't think it's that much.  The implementation of "output() and
 endarg()" should be mostly trivial (I hope we agree on this point), so
 the cost and inconvenience are the caller side.  We'll have to do:

 {{{#!cpp
         // instead of this:
         LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_MEM_DATASRC_DISABLED)
                   .arg(rrclass);

         // we do either:
         LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_MEM_DATASRC_DISABLED)
                   .endarg(rrclass);

         // or this:
         LOG_DEBUG(auth_logger, DBG_AUTH_OPS, AUTH_MEM_DATASRC_DISABLED)
                   .arg(rrclass).output();
 }}}

 The amount of code to be updated is admittedly pretty big, but
 replacement should be quite straightforward.  For future log
 messages, I believe we often copy-paste-modify existing ones, so
 the inconvenience will be even smaller (the developer might even be
 unaware of the trick).  Other potential inconvenience is the risk
 that we forget endarg() or output() and lose the corresponding log
 message.  For that I assume we'll soon enable the logger-check and can
 at least detect by our buildbots.

 Regarding the cost...I really don't see how it could be more expensive
 than the current implementation, both in terms of memory and speed.
 Besides, at least regarding the speed, logging itself is relatively a
 costly operation, and isn't expected to be so frequently called in a
 performance sensitive path.

 So, over all, this seems to me to be really a good deal for such a big
 thing like making a destructor safer.

 All that said...if others are still unhappy about the inconvenience of
 the alternative, I'd at least suggest making the destructor exception
 free in the most trivial way:

 {{{#!cpp
     ~Formatter() {
         if (logger_) {
             try {
                 checkExcessPlaceholders(message_, ++nextPlaceholder_);
                 logger_->output(severity_, *message_);
             } catch (...) {}
             delete message_;
         }
     }
 }}}

-- 
Ticket URL: <http://bind10.isc.org/ticket/1966#comment:5>
BIND 10 Development <http://bind10.isc.org>
BIND 10 Development