Problem with transport lines in BridgeDB's bridge pool assignment files

added bridgedb-0.1.3 bridgedb-0.1.5 component::circumvention/bridgedb owner::isis priority::high resolution::fixed status::closed type::defect labels

This might also be related to #9174 (moved). We found that the bridge of #9174 (moved) sometimes published extrainfo descriptors that didn't include a transport line.

I will try look into this soon.

Replying to asn:

We found that the bridge of #9174 (moved) sometimes published extrainfo descriptors that didn't include a transport line.

That bridge has AssumeReachable 1, because its always fails reachability check without it. I do not know if this could be related to not sometimes publishing transports.

Trac:
Username: hsn

could be #8791 (moved) related?

Trac:
Username: hsn

asn just found that BridgeDB might only parse cached-extrainfo.new and ignores cached-extrainfo. That would explain the pattern above where bridges with "transport" lines go up for two hours and then start at zero again.

The fix is to parse both cached-extrainfo* files in BridgeDB.

Replying to karsten:

asn just found that BridgeDB might only parse cached-extrainfo.new and ignores cached-extrainfo. That would explain the pattern above where bridges with "transport" lines go up for two hours and then start at zero again.

The fix is to parse both cached-extrainfo* files in BridgeDB.

I have a patch for this in branch bug9264_extrainfo_files https://github.com/sysrqb/bridgedb.git

It's pretty simple.

Trac:
Status: new to needs_review

Replying to sysrqb:

parse both cached-extrainfo* files in BridgeDB.

I have a patch for this in branch bug9264_extrainfo_files https://github.com/sysrqb/bridgedb.git

Hm, do you think we should increase that log message, when an extrainfo file throws an exception on open, from warn to error?

BridgeDB was incorrectly using only the new (cached-extrainfo.new) descriptors. I have reverted to using the cached-extrainfo file, but as noted above we don't learn about the extra-info (and pluggable transports) till 2hrs later. sysrqb's fix looks like it should address this (thanks!).

From Karsten's response in the email thread, clarifying extrainfo behavior:

No.  Tonga writes descriptors to cached-extrainfo roughly every two
hours.  It then writes incoming descriptors to cached-extrainfo.new
without touching cached-extrainfo.  Only two hours later, it rewrites
cached-extrainfo and puts all descriptors in it that are still valid.
It also deletes cached-extrainfo.new.

Replying to karsten:

Also, I saw Isis mention this the other day, but I'm not sure if there's already a ticket for it:

{{{ 1093d197b5eab404f30806948367483ad5c7482e email ip=4 flag=stable 112f02b648f19502831103fa50715ce31f8a4a2e email ip=4 flag=stable port=443 112f02b648f19502831103fa50715ce31f8a4a2e email ip=4 flag=stable port=443 transport=obfs3,obfs2 11b3a235c05843fbc57f29a848dee6dc6a6be118 unallocated }}}

Note the duplicate entry for 112f02b648f19502831103fa50715ce31f8a4a2e. The first line shouldn't be there, I guess.

Setting priority to major, because the currently produced bridge pool assignments won't be useful for analysis.

Are those entries adjacent? Or was this output produced with sort? I noticed that for each assignment period a line is written 3 times for each bridge (but the lines are not consecutive). That suggests that the bug might have something to do with the function BridgeSplitter.dumpAssignments() in Bridges.py:923 ... but it isn't clear to me why that occurs yet.

Good point. Lines are not adjacent in the original assignments.log file, I think. The sanitizer in metrics-db sorts lines, and what I pasted above is from sanitized assignments.

Still no progress? Again, we're losing data here. The July pool assignment archives will be mostly useless for analysis, and Onionoo serves useless data to bridge operators. Please fix ASAP. Thanks.

As a hint on what might be going on, I read some BridgeDB logs with sysrqb and we noticed that when dumpAssignments() is run, we get multiple "%s supports %d transports" messages for each bridge.

This probably means that the list self.bridges contains duplicate bridges.

I read through some of the settings in the running instance of BridgeDB's bridgedb.conf file. There it specifies:

$ cat bridgedb.conf | grep descriptors
# Files from which we read bridge descriptors, on start and on SIGHUP.
BRIDGE_FILES = [ "../from-authority/bridge-descriptors" ]

and in Main.py, in the global CONFIG variable which is used for testing, these are:

lib/bridgedb/Main.py:    BRIDGE_FILES = [ "./cached-descriptors", "./cached-descriptors.new" ],

In the from-authority directory I found all three of these files, all with recent modification times, and the running BridgeDB process was not called with the '--testing' option, so it should only be reading the 'bridge-descriptors' file.

I'm fairly sure that if I change BRIDGE_FILES in the running instance's config to ["./cached-descriptors", "./cached-descriptors.new"] that it'll fix this, but I am nervous to change things without someone else who knows BridgeDB really well being available to help (I don't know how maintenance and deployments are done yet).

Are you sure you're seeing recent cached-descriptors[.new] files on ponticum, not cached-extrainfo[.new]?

It appears that whatever is causing this was put into production on 2013/08/14. Does ponticum have any sort of log that will be able to tell us what changed that day? I'm still going through commits that were made to bridgedb prior to that date. Does the bridgedb logfile go back that far?

I determined the date by doing a lovely binary search through the bridge-pool-assignments on metrics and running

for i in ./*/*; do echo -n "$i: "; cat $i | awk '{ print $1; }' \
   | uniq -d | wc -l; done | grep -v 0$ | head

over the month. August 14 was the first day that contained duplicates.

./14/2012-08-14-05-00-11: 1
./14/2012-08-14-05-30-11: 1
./14/2012-08-14-06-00-11: 1
./14/2012-08-14-06-30-12: 1
./14/2012-08-14-07-00-12: 1
./14/2012-08-14-07-30-12: 1
./14/2012-08-14-08-00-04: 1
./14/2012-08-14-08-30-04: 1
./14/2012-08-14-09-00-05: 1
./14/2012-08-14-09-30-06: 1

This isn't an answer, but at least it gives us another avenue to attack it.

I've written an ugly hack that should solve this problem temporarily until we're able to determine what is causing it. It's branch bug9264_temporary_fix on https://github.com/sysrqb/bridgedb.git

Did I mention this is a temporary hack?

Replying to karsten:

Are you sure you're seeing recent cached-descriptors[.new] files on ponticum, not cached-extrainfo[.new]?

The latter, oops, 5AM hacking #FTL.

Replying to sysrqb:

I've written an ugly hack that should solve this problem temporarily until we're able to determine what is causing it. It's branch bug9264_temporary_fix on https://github.com/sysrqb/bridgedb.git

Did I mention this is a temporary hack?

Got it. Looks good, thanks, sysrqb! I merged this here into my master branch, to go into the next redeploy that I am about to do.

Trac:
Owner: N/A to isis
Status: needs_review to accepted

Deployed from branch deploy/2013-08-09-isis-5332-9156-9264.

Trac:
Status: accepted to needs_information

I can confirm that bridge pool assignment files now contain sane numbers of bridges with transports:

$ grep -c transport *
2013-08-12-00-04-05:474
2013-08-12-00-34-08:475
2013-08-12-01-03-51:475
2013-08-12-01-34-01:475
2013-08-12-02-04-01:490
2013-08-12-02-34-03:494
2013-08-12-03-04-09:493
2013-08-12-03-33-57:494
2013-08-12-04-03-56:493
2013-08-12-04-33-55:493
2013-08-12-05-03-53:492
2013-08-12-05-34-08:492
2013-08-12-06-03-57:490
2013-08-12-06-33-57:491
2013-08-12-07-03-51:490
2013-08-12-07-34-32:459
2013-08-12-08-05-22:465
2013-08-12-08-34-03:476
2013-08-12-09-03-52:491
2013-08-12-09-33-56:490
2013-08-12-10-03-38:490
2013-08-12-10-33-59:490
2013-08-12-11-05-10:510
2013-08-12-11-33-38:509

So, I think this concludes the ticket. Optimistically closing. If this was wrong, please re-open. Thanks everyone!

Trac:
Resolution: N/A to fixed
Status: needs_information to closed

Problem with transport lines in BridgeDB's bridge pool assignment files

Child items 0

Activity