Opened 8 years ago

Last modified 4 years ago

#1966 new defect

logger formatter does too much in the destructor

Reported by: jinmei Owned by:
Priority: medium Milestone: Outstanding Tasks
Component: logging Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: Core Feature Depending on Ticket:
Estimated Difficulty: 16 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description (last modified by jinmei)

While working on #1964, I noticed the destructor of the log::Formater
class had quite a lot of responsibility. In the context of #1964, the
check mode can throw an exception, which is obviously bad. Even with
forgetting it, the destructor calls Logger::output(), which internally
calls log4cplus modules that we cannot directly control and cannot be
really sure if it's really safe.

Although I agree it's a neat trick to let the destructor finish the
output, it seems to me quite fragile to rely on at such a sensitive
place as a destructor.

I propose an alternative approach, which should be much safer in this
regard, and hopefully will not damage the convenience of the current
notation too much:

  • introduce another method to Formatter, say, output(). It calls logger_->output(). In the check mode, it also performs the "excess placeholder" check, and throws an exception if it finds an error. It records the fact it's called so that it cannot be called more than once (if broken, throw).
  • (not absolutely necessary but for convenience) also introduce another additional method, say, endarg(). It's similar to arg(), but it also calls the newly introduced output().
  • the Formatter constructor now only does simpler and safer cleanup, such as deleting the message (btw, it seems to be possible that the message can leak depending on how the formatter is constructed. We should also fix that). Also, in the check mode, it checks whether output() has been called (or an exception has been thrown due to the format check error), and if not, abort the program by assert() (note that we cannot throw here).
  • The caller is responsible for completing the logging statements with either endarg() or explicit output(). If broken, we'll lose that log message in the normal mode, and we should be able to detect that via an automated test that uses the check mode.

A bonus of this approach is that we can now use exception for the
"excess placeholder" check, which was changed to assert() in #1964
as an urgent care regression fix.

Subtickets

Change History (9)

comment:1 Changed 8 years ago by jinmei

  • Summary changed from logger formatter does too much in the constructor to logger formatter does too much in the destructor

comment:2 Changed 8 years ago by jinmei

  • Description modified (diff)

comment:3 Changed 8 years ago by jinmei

  • Sub-Project changed from DNS to Core

comment:4 follow-up: Changed 8 years ago by 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 believe this change is not worth the cost of inconvenience and change itself.

comment:5 in reply to: ↑ 4 ; follow-up: Changed 8 years ago by jinmei

Replying to 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:

    // 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:

    ~ 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:

        // 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:

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

comment:6 in reply to: ↑ 5 Changed 6 years ago by muks

Replying to jinmei:

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:

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

#3314 has been filed to take care of this for the short-term.

comment:7 Changed 5 years ago by tomek

  • Milestone set to Remaining BIND10 tickets

comment:8 Changed 4 years ago by tomek

  • Milestone changed from Remaining BIND10 tickets to DHCP Outstanding Tasks

As part of bug scrubbing during Kea 1.0, we decided to move a number of tickets to DHCP Outstanding.

comment:9 Changed 4 years ago by tomek

  • Milestone changed from DHCP Outstanding Tasks to Outstanding Tasks

Milestone renamed

Note: See TracTickets for help on using tickets.