Opened 9 years ago

Closed 8 years ago

Last modified 7 years ago

#2190 closed defect (fixed)

Possible reentrant calls to libevent from libevent logging callback

Reported by: nickm Owned by: rransom
Priority: Medium Milestone: Tor: 0.2.2.x-final
Component: Core Tor/Tor Version:
Severity: Keywords:
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Right now, we give Libevent a logging callback that can call into our logging system, which can in turn call into our networking code (to send messages to the controller), which can re-invoke libevent. That's bad, since Libevent's functions are pretty much all non-reentrant.

This bug has existed since 0.1.0.2-rc (since we've had log messages sent to controllers since 0.0.9pre5... and we've logged messages from libevent since 0.1.0.2-rc).

So why aren't we seeing this bug all the time? First, Libevent logs relatively little by default, and many of the places it logs from are harmless in practice since we don't call them reentrantly when sending log messages to the controller.

So this will probably cause big trouble only for cases where Libevent debug-level logging is enabled AND the user has a controller watching for low-severity log messages. Of course, if there are bugs that provoke libevent warnings, all bets are off.

Child Tickets

Change History (15)

comment:1 Changed 9 years ago by nickm

The obvious easy fix is to never send log messages that arrive from libevent to any callback-based log backend.

There is a harder fix: we could have a fix where instead of blocking libevent->controller log messages, we queue them in a list somewhere, and add a callback to play them back later. This is probably a good idea for 0.2.3 (and maybe 0.2.2) since it is not so great to keep controller users from seeing warnings.

comment:2 Changed 9 years ago by nickm

Status: newneeds_review

I now have a simple fix in my public repo as bug2190. There is an 0.2.1 backport as bug2190_021.

comment:3 Changed 9 years ago by nickm

Also see branch "bug2190_the_hard_way" that defers the messages rather than dropping them. Needs testing and review. Based on bug2190 branch. Could merge into 0.2.2 or master.

comment:4 Changed 9 years ago by rransom

Owner: changed from nickm to rransom
Status: needs_reviewassigned

All three branches look good to me.

comment:5 Changed 8 years ago by rransom

Status: assignedneeds_review

I'm resetting the status of this ticket to needs_review, because I think it's been forgotten about since I accidentally assigned it to myself.

comment:6 Changed 8 years ago by cypherpunks

Branch "bug2190_the_hard_way" possible incomplete:

  messages = pending_cb_messages;
  pending_cb_messages = smartlist_create();
  do {

...

    smartlist_clear(messages);

    messages_tmp = pending_cb_messages;
    pending_cb_messages = messages;
    messages = messages_tmp;
  } while (smartlist_len(messages));

Because if no one can change pending_cb_messages during do{}while() the the last part is equal at least to:

    smartlist_clear(messages);

  } while (0);

comment:7 in reply to:  6 ; Changed 8 years ago by rransom

Replying to cypherpunks:

Because if no one can change pending_cb_messages during do{}while() the the last part is equal at least to:

The call to lf->callback can change pending_cb_messages. That's why he moved pending_cb_messages into a temporary variable messages and then put a new list in pending_cb_messages.

comment:8 in reply to:  7 ; Changed 8 years ago by cypherpunks

Replying to rransom:

The call to lf->callback can change pending_cb_messages.

No, it's can't.

comment:9 in reply to:  8 Changed 8 years ago by cypherpunks

Replying to cypherpunks:

Replying to rransom:

The call to lf->callback can change pending_cb_messages.

No, it's can't.

It was wrong statement. Yes, it can.
Calling of lf->callback can to append a new members of pending_cb_messages.

comment:10 Changed 8 years ago by rransom

boboper points out that the following statement in logv is not safe:

  if (smartlist_len(pending_cb_messages))
    flush_pending_log_callbacks();

If two LD_NOCB messages were logged in a row, logv would call flush_pending_log_callbacks while handling a LD_NOCB message.

Fixed in 4a9d60734ce47cb3b5cb254e522116cd26b4823f. See bug2190_the_hard_way ( ssh://mob@repo.or.cz/srv/git/tor/rransom.git bug2190_the_hard_way ).

comment:11 Changed 8 years ago by rransom

bug2190_the_hard_way would also add an entry to pending_cb_messages for each message, for each logfile_t with a callback. Fixed in cc051f9aca96b55533953cfcc10c86f9fe1e7b9a.

comment:12 Changed 8 years ago by nickm

Looks better now, though I think there's an extra set of parenthesis in 4a9d60 for no apparent reason.

Right now I'm thinking that 0.2.1 should get the "easy" fix and 0.2.2.x and master should get the"hard" fix.

comment:13 in reply to:  12 Changed 8 years ago by rransom

Replying to nickm:

Looks better now, though I think there's an extra set of parenthesis in 4a9d60 for no apparent reason.

I'm not enough of an expert on C's order of operations to know whether one of those sets of parentheses can be removed safely. I would prefer to keep the quick check of the log domain before the slightly slower function call, and I'm not sure that ! binds tighter than && or that & binds tighter than !. I think it's easier to read as is.

Right now I'm thinking that 0.2.1 should get the "easy" fix and 0.2.2.x and master should get the"hard" fix.

I agree.

comment:14 Changed 8 years ago by nickm

Resolution: fixed
Status: needs_reviewclosed

applied to 0.2.1 through master.

comment:15 Changed 7 years ago by nickm

Component: Tor ClientTor
Note: See TracTickets for help on using tickets.