Opened 7 years ago

Closed 7 years ago

#8880 closed defect (not a bug)

Fix log message saying what fraction of paths we can likely build

Reported by: karsten Owned by:
Priority: Medium Milestone: Tor: 0.2.4.x-final
Component: Core Tor/Tor Version:
Severity: Keywords: tor-client shadow
Cc: robgjansen Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

When trying to get Shadow working with Tor master, Rob and I came across this strange log message:

[notice] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 5/5, and can only build 020274120f likely paths. (We have 05001111756f guards bw, 1005016602000f midpoint bw, and 013634243140f exit bw.)

I tried various things, but didn't find out how to fix this. Here's a workaround that may help track down the bug:

diff --git a/src/or/nodelist.c b/src/or/nodelist.c
index 178f084..d566fd9 100644
--- a/src/or/nodelist.c
+++ b/src/or/nodelist.c
@@ -1373,9 +1373,9 @@ compute_frac_paths_available(const networkstatus_t *consensus,
     f_exit = f_myexit;
 
   tor_asprintf(status_out,
-               "%d%% of guards bw, "
-               "%d%% of midpoint bw, and "
-               "%d%% of exit bw",
+               "%d percent of guards bw, "
+               "%d percent of midpoint bw, and "
+               "%d percent of exit bw",
                (int)(f_guard*100),
                (int)(f_mid*100),
                (int)(f_exit*100));
@@ -1471,7 +1471,7 @@ update_router_have_minimum_dir_info(void)
     if (paths < get_frac_paths_needed_for_circs(options,consensus)) {
       tor_snprintf(dir_info_status, sizeof(dir_info_status),
                    "We need more %sdescriptors: we have %d/%d, and "
-                   "can only build %d%% of likely paths. (We have %s.)",
+                   "can only build %d percent of likely paths. (We have %s.)",
                    using_md?"micro":"", num_present, num_usable,
                    (int)(paths*100), status);
       /* log_notice(LD_NET, "%s", dir_info_status); */

Output is now:

[notice] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 4/5, and can only build 46 percent of likely paths. (We have 55 percent of guards bw, 84 percent of midpoint bw, and 100 percent of exit bw.)

Child Tickets

Change History (8)

comment:1 Changed 7 years ago by nickm

For me, I get:

May 15 10:45:32.000 [notice] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 96/3458, and can only build 0% of likely paths. (We have 3% of guards bw, 2% of midpoint bw, and 2% of exit bw.)

Could anything weird be going on with your libc and/or your compiler?

Does this occur with 0.2.4.x as well?

comment:2 in reply to:  1 Changed 7 years ago by karsten

Cc: robgjansen added
Status: newneeds_information

Replying to nickm:

For me, I get:

May 15 10:45:32.000 [notice] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 96/3458, and can only build 0% of likely paths. (We have 3% of guards bw, 2% of midpoint bw, and 2% of exit bw.)

Could anything weird be going on with your libc and/or your compiler?

Oh, interesting. Could be Shadow-related then. Cc'ing Rob, maybe he has an idea? (Not that this issue is particularly important, but maybe it hides more serious issues.)

Does this occur with 0.2.4.x as well?

Yes, we found this in 0.2.4.10-alpha. https://github.com/shadow/shadow/issues/117

comment:3 Changed 7 years ago by nickm

Keywords: tor-client shadow added
Milestone: Tor: 0.2.5.x-finalTor: 0.2.4.x-final

comment:4 Changed 7 years ago by robgjansen

I very briefly looked at the code (the %d%% is causing problems). Shadow intercepts Tor's 'logv' function, but doesn't call 'format_msg'. Is that the issue? Otherwise, Shadow takes the va_list and passes it to g_logv, which I assume should handle the %d%% format correctly.

This is where I wish Tor was slightly more modular (read: Shadow could selectively intercept functions). Shadow intercepts the 'logv' function in 'log.c' so that it can push the log message through the simulator's logging mechanism. That means every time changes are made to logv, Shadow's version becomes out of date. Ideally [for Shadow], the 'write_all' at the end of 'logv' would be moved to a new 'logv_write_all' function. Then, Shadow could intercept 'logv_write_all' and reduce code duplication on Shadow's end.

comment:5 in reply to:  4 Changed 7 years ago by nickm

Replying to robgjansen:

This is where I wish Tor was slightly more modular (read: Shadow could selectively intercept functions). Shadow intercepts the 'logv' function in 'log.c' so that it can push the log message through the simulator's logging mechanism. That means every time changes are made to logv, Shadow's version becomes out of date. Ideally [for Shadow], the 'write_all' at the end of 'logv' would be moved to a new 'logv_write_all' function. Then, Shadow could intercept 'logv_write_all' and reduce code duplication on Shadow's end.

"Unless someone like you cares a whole awful lot, nothing is going to get better. It's not!" -- _The Lorax_ by Dr Seuss

I'd take a patch to add that.

comment:6 Changed 7 years ago by robgjansen

Long story short, this was a scallion bug: (msg) -> ("%s", msg) fixed the problem. More details here.

Nevermind about the patch. I'm now using add_callback_log() instead of intercepting logv().

On that front, calling add_callback_log() before tor_init() causes Tor to lose the callback somewhere. That may or may not be intended, but this currently seems to work:

add_callback_log()
tor_init()
add_callback_log()

comment:7 in reply to:  6 Changed 7 years ago by robgjansen

Replying to robgjansen:

Long story short, this was a scallion bug: (msg) -> ("%s", msg) fixed the problem. More details here.

BTW, I believe this ticket can be closed.

comment:8 Changed 7 years ago by karsten

Resolution: not a bug
Status: needs_informationclosed

I can confirm that the "%d%%" issue is now fixed in Shadow. There's a new logging problem in Shadow, but that's clearly unrelated to tor. Let's have that discussion in Shadow's bug tracker. Closing. Thanks!

Note: See TracTickets for help on using tickets.