[tor-bugs] #1980 [Tor Client]: Bug: Circuit somehow completed a hop while the network was not live

[Tor Bug Tracker & Wiki]

#1980: Bug: Circuit somehow completed a hop while the network was not live
------------------------+---------------------------------------------------
 Reporter:  arma        |       Owner:  mikeperry         
     Type:  defect      |      Status:  new               
 Priority:  major       |   Milestone:  Tor: 0.2.2.x-final
Component:  Tor Client  |     Version:                    
 Keywords:              |      Parent:                    
------------------------+---------------------------------------------------
 {{{
 Sep 28 16:23:29.567 [warn] circuit_build_times_network_close(): Bug:
 Circuit somehow completed a hop while the network was not live. Network
 was last live at 2010-09-28 16:22:28, but circuit launched at 2010-09-28
 16:22:28. It's now 2010-09-28 16:23:29.
 Sep 28 16:25:31.815 [warn] circuit_build_times_network_close(): Bug:
 Circuit somehow completed a hop while the network was not live. Network
 was last live at 2010-09-28 16:24:30, but circuit launched at 2010-09-28
 16:24:30. It's now 2010-09-28 16:25:31.
 Sep 28 16:28:34.211 [warn] circuit_build_times_network_close(): Bug:
 Circuit somehow completed a hop while the network was not live. Network
 was last live at 2010-09-28 16:27:33, but circuit launched at 2010-09-28
 16:27:33. It's now 2010-09-28 16:28:34.
 Sep 28 16:35:00.010 [warn] circuit_build_times_network_close(): Bug:
 Circuit somehow completed a hop while the network was not live. Network
 was last live at 2010-09-28 16:33:59, but circuit launched at 2010-09-28
 16:33:59. It's now 2010-09-28 16:35:00.
 Sep 28 16:50:15.030 [warn] circuit_build_times_network_close(): Bug:
 Circuit somehow completed a hop while the network was not live. Network
 was last live at 2010-09-28 16:49:14, but circuit launched at 2010-09-28
 16:49:14. It's now 2010-09-28 16:50:15.
 }}}

 If I look closer at them, it seems we're not actually completing a hop:
 {{{
 Sep 28 16:25:31.815 [warn] circuit_build_times_network_close(): Bug:
 Circuit somehow completed a hop while the network was not live. Network
 was last live at 2010-09-28 16:24:30, but circuit launched at 2010-09-28
 16:24:30. It's now 2010-09-28 16:25:31.
 Sep 28 16:25:31.816 [debug] circuit_build_times_add_time(): Adding circuit
 build time 2147483646
 Sep 28 16:25:31.816 [info] circuit_expire_building(): Abandoning circ
 128.31.0.34:9009:56334 (state 0:doing handshakes, purpose 13)
 Sep 28 16:25:31.816 [info] exit circ (length 3, exit Amunet11):
 $4C17FB532E20B2A8AC199441ECD2B0177B39E4B1(open) Pandora14(waiting for
 keys) Amunet11(closed)
 Sep 28 16:25:31.816 [debug] connection_or_send_destroy(): Sending destroy
 (circID 56334).
 }}}
 or
 {{{
 Sep 28 16:50:15.030 [warn] circuit_build_times_network_close(): Bug:
 Circuit somehow completed a hop while the network was not live. Network
 was last live at 2010-09-28 16:49:14, but circuit launched at 2010-09-28
 16:49:14. It's now 2010-09-28 16:50:15.
 Sep 28 16:50:15.031 [debug] circuit_build_times_add_time(): Adding circuit
 build time 2147483646
 Sep 28 16:50:15.031 [info] circuit_expire_building(): Abandoning circ
 128.31.0.34:9009:56361 (state 0:doing handshakes, purpose 13)
 Sep 28 16:50:15.031 [info] exit circ (length 3, exit morphium2):
 $4C17FB532E20B2A8AC199441ECD2B0177B39E4B1(open)
 $F08F537D245A65D9C242359983718A19650A25F7(open) morphium2(waiting for
 keys)
 Sep 28 16:50:15.031 [debug] connection_or_send_destroy(): Sending destroy
 (circID 56361).
 }}}

 I'm using a bridge.

 Also, it's a nice coincidence that "circuit launched at x" and "network
 was last live at y" are always x=y.

-- 
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/1980>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online