Opened 7 years ago

Last modified 6 months ago

#8593 assigned defect

Circuit build timeout not respected?

Reported by: karsten Owned by:
Priority: High Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: 0.2.4.9-alpha
Severity: Normal Keywords: tor-client cbt timeout
Cc: mikeperry, nickm Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

I'm currently testing my Torperf rewrite. I noticed that a few circuit builds take far longer than the circuit-build timeout. Still, these circuit builds are not aborted and the resulting circuits get streams attached. Isn't the CBT stuff supposed to prevent just that?

Below is an example (reformatted). Notice the timestamps of the CIRC LAUNCHED and the CIRC EXTENDED event:

2013-03-26 12:57:05+0000 CIRC 176 LAUNCHED
  BUILD_FLAGS=NEED_CAPACITY PURPOSE=GENERAL
  TIME_CREATED=2013-03-26T12:57:05.992579
2013-03-26 12:58:44+0000 CIRC 176 EXTENDED
  $8BBE900C29D4B5D3FC727DB65140EA0A5EC94C19=kennkeintor
  BUILD_FLAGS=NEED_CAPACITY PURPOSE=GENERAL
  TIME_CREATED=2013-03-26T12:57:05.992579
2013-03-26 12:58:44+0000 CIRC 176 EXTENDED
  $8BBE900C29D4B5D3FC727DB65140EA0A5EC94C19=kennkeintor,
  $0AC01745501396F338291248032E77317079A02D=KandHResearchCo
  BUILD_FLAGS=NEED_CAPACITY PURPOSE=GENERAL
  TIME_CREATED=2013-03-26T12:57:05.992579
2013-03-26 12:58:45+0000 CIRC 176 EXTENDED
  $8BBE900C29D4B5D3FC727DB65140EA0A5EC94C19=kennkeintor,
  $0AC01745501396F338291248032E77317079A02D=KandHResearchCo,
  $3E5693C4B0FCD8B42153869494421164E42A9FE0=chaoscomputerclub29
  BUILD_FLAGS=NEED_CAPACITY PURPOSE=GENERAL
  TIME_CREATED=2013-03-26T12:57:05.992579
2013-03-26 12:58:45+0000 CIRC 176 BUILT
  $8BBE900C29D4B5D3FC727DB65140EA0A5EC94C19=kennkeintor,
  $0AC01745501396F338291248032E77317079A02D=KandHResearchCo,
  $3E5693C4B0FCD8B42153869494421164E42A9FE0=chaoscomputerclub29
  BUILD_FLAGS=NEED_CAPACITY PURPOSE=GENERAL
  TIME_CREATED=2013-03-26T12:57:05.992579
2013-03-26 13:01:01+0000 STREAM 379 SENTCONNECT 176
  54.242.189.124:80
2013-03-26 13:01:02+0000 STREAM 379 REMAP 176 54.242.189.124:80
  SOURCE=EXIT
2013-03-26 13:01:02+0000 STREAM 379 SUCCEEDED 176 54.242.189.124:80
2013-03-26 13:01:04+0000 STREAM 379 CLOSED 176 54.242.189.124:80
  REASON=END REMOTE_REASON=DONE
2013-03-26 13:02:09+0000 CIRC 176 CLOSED
  $8BBE900C29D4B5D3FC727DB65140EA0A5EC94C19=kennkeintor,
  $0AC01745501396F338291248032E77317079A02D=KandHResearchCo,
  $3E5693C4B0FCD8B42153869494421164E42A9FE0=chaoscomputerclub29
  BUILD_FLAGS=NEED_CAPACITY PURPOSE=GENERAL
  TIME_CREATED=2013-03-26T12:57:05.992579 REASON=FINISHED

The CBT was around 3 seconds at that time as reported in a BUILDTIMEOUT_SET event. This is Tor version 0.2.4.9-alpha-dev (git-123daffb600cb1b5). I can easily modify and re-run this tool to gather more data if required.

Child Tickets

Change History (21)

comment:1 Changed 7 years ago by mikeperry

Milestone: Tor: 0.2.4.x-final
Owner: set to mikeperry
Priority: normalmajor
Status: newassigned

Circuit timeout is no longer counted from the launch event due to fixes from #3443. It is now counted from circuit_deliver_create_cell(), so as to avoid sometimes counting ORCONN setup time and sometimes not.

My guess is that what *might* have happened was that there was an ORCONN connection that needed to be made to satisfy the first hop between these two events:

2013-03-26 12:57:05+0000 CIRC 176 LAUNCHED

BUILD_FLAGS=NEED_CAPACITY PURPOSE=GENERAL
TIME_CREATED=2013-03-26T12:57:05.992579

2013-03-26 12:58:44+0000 CIRC 176 EXTENDED

$8BBE900C29D4B5D3FC727DB65140EA0A5EC94C19=kennkeintor
BUILD_FLAGS=NEED_CAPACITY PURPOSE=GENERAL
TIME_CREATED=2013-03-26T12:57:05.992579

Unfortunately we don't currently have an event (other than also watching for ORCONN events) to verify this. Perhaps we should create a CIRC MINOR event here or something?

comment:2 Changed 7 years ago by mikeperry

Status: assignedneeds_information

comment:3 Changed 7 years ago by mikeperry

Cc: nickm added

FTR: I don't actually think this is a bug, but we should provide something here so we can keep an eye on CBT and verify this. It's good that Karsten caught this with torperf, and we want to preserve that ability, too.

comment:4 Changed 7 years ago by mikeperry

To move this along since I was probably too vague above, I see two possibilities:

  1. Simply delay the LAUNCHED event until we actually send the create cell.
  2. Create a CIRC_MINOR event for the create cell.

I think approach 1 will be simpler and more consistent with people measuring build times with their controllers to spot-check CBT.

comment:5 Changed 7 years ago by nickm

01:15 < nickm> IMO both 'created' and 'sent create' should get events, one of 
               which can be a CIRC_MINOR.
01:16 < nickm> I think that if you're going to have the 'sent create' be the 
               LAUNCHED, then if you're going to fail a circuit that hasn't yet 
               launched, you should send a launched immediately before
01:16 < nickm> which would give LAUNCHED tricky semantics
01:16 < nickm> I guess that means I like approach 2.  I'm not sure whether I 
               favor it for 0.2.4 or early-0.2.5.

comment:6 Changed 7 years ago by karsten

Ah, thanks for explaining this!

For Torperf, I guess any of the suggested solutions would work, as long as there's some way to learn when the build timeout starts for a given circuit. Having something in early 0.2.5 works for me, though it would mean that Torperf wouldn't print out any build times for earlier version; which is acceptable.

comment:7 Changed 7 years ago by mikeperry

Keywords: MikePerry201304 added

karsten: How soon will you have at least one public torperf on 0.2.5.x (ie such that I can download extrainfo outputs for it)? Do you have any already following origin/master right now?

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

Replying to mikeperry:

karsten: How soon will you have at least one public torperf on 0.2.5.x (ie such that I can download extrainfo outputs for it)? Do you have any already following origin/master right now?

I hope to have a public Torperf on 0.2.5.x at some time this month when the rewrite is ready. Note that there won't be separate .data and .extradata files anymore, but just one output file formerly known as .mergedata. I also just started a 50 KiB Torperf running Tor 0.2.5.x on an EC2 instance. I'll upload raw logs for you tomorrow.

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

Replying to karsten:

[...] I'll upload raw logs for you tomorrow.

See https://people.torproject.org/~karsten/volatile/perfd.log.gz. Lines containing "START" are very close to .mergedata lines, the rest is, erm, additional information.

comment:10 in reply to:  9 Changed 7 years ago by karsten

Replying to karsten:

Replying to karsten:

[...] I'll upload raw logs for you tomorrow.

See https://people.torproject.org/~karsten/volatile/perfd.log.gz. Lines containing "START" are very close to .mergedata lines, the rest is, erm, additional information.

Updated the link with a log file of a Torperf that has been running until a few days ago. Let me know if you need anything else there.

comment:11 Changed 7 years ago by mikeperry

Keywords: MikePerry201306 added; MikePerry201304 removed

I will see about doing this when we get closer to doing more performance work for 0.2.5.x.

comment:12 Changed 7 years ago by andrea

Milestone: Tor: 0.2.4.x-finalTor: 0.2.5.x-final

comment:13 Changed 6 years ago by mikeperry

Keywords: MikePerry201308 added; MikePerry201306 removed

comment:14 Changed 6 years ago by mikeperry

Keywords: MikePerry201308 removed

comment:15 Changed 6 years ago by nickm

Milestone: Tor: 0.2.5.x-finalTor: 0.2.???

comment:16 Changed 3 years ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:17 Changed 3 years ago by nickm

Keywords: tor-03-unspecified-201612 added
Milestone: Tor: 0.3.???Tor: unspecified

Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.

comment:18 Changed 3 years ago by nickm

Keywords: tor-03-unspecified-201612 removed

Remove an old triaging keyword.

comment:19 Changed 3 years ago by nickm

Keywords: cbt timeout added
Severity: Normal

Any updates here? Is this still a thing we should do?

comment:20 Changed 6 months ago by arma

Karsten, is this torperf still a thing, or did it get replaced with onionperf? And if it got replaced, does the new one have this issue too?

comment:21 Changed 6 months ago by gaba

Owner: mikeperry deleted
Status: needs_informationassigned
Note: See TracTickets for help on using tickets.