Circuit build timeout not respected?
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.