[tor-bugs] #3834 [Torflow]: Postgre bandwidth scanner has halted on moria

[Tor Bug Tracker & Wiki]

#3834: Postgre bandwidth scanner has halted on moria
-----------------------+----------------------------------------------------
 Reporter:  mikeperry  |          Owner:  aagbsn
     Type:  defect     |         Status:  new   
 Priority:  major      |      Milestone:        
Component:  Torflow    |        Version:        
 Keywords:             |         Parent:        
   Points:             |   Actualpoints:        
-----------------------+----------------------------------------------------

Comment(by aagbsn):

 Unfortunately the fix (call TorCtl.Connection.close() in the atexit
 handler, see: github link above) does not work 100% of the time. Here is a
 traceback:

 DEBUG[Fri Sep 02 06:34:28 2011]:0.622465133667 CIRC 2396 CLOSED
 $0C8B86A3FB22EF3E92ABEEA80ADF879A26B59BA8,$6620BECAFC3AB3E2A255A975239F6EF4EC542F16
 REASON=REQUESTED
 DEBUG[Fri Sep 02 06:34:28 2011]:Close refcount 0 for
 0C8B86A3FB22EF3E92ABEEA80ADF879A26B59BA8
 DEBUG[Fri Sep 02 06:34:28 2011]:Close refcount 0 for
 6620BECAFC3AB3E2A255A975239F6EF4EC542F16
 DEBUG[Fri Sep 02 06:34:28 2011]:1314945267.4 0.620501041412 CIRC 2402
 CLOSED
 $7F4C602A9E0498F244AAA002783E7B8DEB4875EF,$FCC3151A288A58AAD8B6D81E2FB3244DE6526375
 REASON=REQUESTED
 DEBUG[Fri Sep 02 06:34:28 2011]:0.638204097748 CIRC 2402 CLOSED
 $7F4C602A9E0498F244AAA002783E7B8DEB4875EF,$FCC3151A288A58AAD8B6D81E2FB3244DE6526375
 REASON=REQUESTED
 DEBUG[Fri Sep 02 06:34:28 2011]:Close refcount 0 for
 7F4C602A9E0498F244AAA002783E7B8DEB4875EF
 DEBUG[Fri Sep 02 06:34:28 2011]:Close refcount 0 for
 FCC3151A288A58AAD8B6D81E2FB3244DE6526375
 DEBUG[Fri Sep 02 06:36:50 2011]:Ignoring stream: 3047
 DEBUG[Fri Sep 02 06:36:51 2011]:Wrote stats
 NOTICE[Fri Sep 02 06:36:51 2011]:Tor closed control connection. Exiting
 event thread.
 DEBUG[Fri Sep 02 06:36:51 2011]:Ignoring stream: 3047
 DEBUG[Fri Sep 02 06:36:51 2011]:Ignoring stream: 3047
 DEBUG[Fri Sep 02 06:36:52 2011]:Deleting ignored stream: 3045

 ...snip...

 DEBUG[Fri Sep 02 06:36:54 2011]:78.6796159744 CIRC 2417 EXTENDED
 $AC92AA2248170F4DA7B886932CD430AB0945D2B1
 DEBUG[Fri Sep 02 06:36:54 2011]:Ignoring circ 2417
 DEBUG[Fri Sep 02 06:36:54 2011]:78.6807179451 CIRC 2417 BUILT
 $AC92AA2248170F4DA7B886932CD430AB0945D2B1
 DEBUG[Fri Sep 02 06:36:54 2011]:Ignoring circ 2417
 DEBUG[Fri Sep 02 06:36:54 2011]:Ignoring stream: 3066
 DEBUG[Fri Sep 02 06:36:55 2011]:Ignoring stream: 3066
 DEBUG[Fri Sep 02 06:36:55 2011]:Deleting ignored stream: 3066
 WARN[Fri Sep 02 06:36:55 2011]:No event for: 650 NEWCONSENSUS
 Traceback (most recent call last):
   File "../../TorCtl/TorCtl.py", line 712, in _eventLoop
     self._handleFn(timestamp, reply)
   File "../../TorCtl/TorCtl.py", line 1337, in _handle1
     self._map1.get(event.event_name, self.unknown_event)(event)
   File "../../TorCtl/PathSupport.py", line 1834, in new_consensus_event
     TorCtl.ConsensusTracker.new_consensus_event(self, n)
   File "../../TorCtl/TorCtl.py", line 1679, in new_consensus_event
     self._read_routers(self.ns_map.values())
   File "../../TorCtl/TorCtl.py", line 1597, in _read_routers
     routers = self.c.read_routers(nslist) # Sets .down if 3,4,5
   File "../../TorCtl/TorCtl.py", line 1073, in read_routers
     r = self.get_router(ns)
   File "../../TorCtl/TorCtl.py", line 1054, in get_router
     desc = self.sendAndRecv("GETINFO desc/id/" + ns.idhex + "\r\n")[0][2]
   File "../../TorCtl/TorCtl.py", line 862, in sendAndRecv
     lines = self._sendImpl(self._doSend, msg)
   File "../../TorCtl/TorCtl.py", line 729, in _sendImpl
     raise self._closedEx
 TorCtlClosed

 This seems like it may be related to #1329; perhaps atagar may have some
 insight.

 Replying to [comment:7 aagbsn]:
 > This is caused by the main thread exiting before the eventLoop thread;
 because we weren't exiting cleanly. I have a fix for this in my testing
 branch that just needs_review before we can merge it.
 >
 >
 https://github.com/aagbsn/torflow/commit/09f232bffa3cf51db21c53c81e544ad977bcb335
 >
 > Replying to [comment:5 arma]:
 > > Scanner 4 has a traceback:
 > > {{{
 > > Exception in thread EventLoop (most likely raised during interpreter
 shutdown):
 > > Traceback (most recent call last):
 > >   File "/usr/lib/python2.5/threading.py", line 486, in
 __bootstrap_inner
 > >   File "/usr/lib/python2.5/threading.py", line 446, in run
 > >   File "../../TorCtl/TorCtl.py", line 715, in _eventLoop
 > >   File "../../TorCtl/TorUtil.py", line 360, in plog
 > >   File "/usr/lib/python2.5/logging/__init__.py", line 1056, in log
 > >   File "/usr/lib/python2.5/logging/__init__.py", line 1100, in _log
 > >   File "/usr/lib/python2.5/logging/__init__.py", line 1080, in
 makeRecord
 > >   File "/usr/lib/python2.5/logging/__init__.py", line 258, in __init__
 > > <type 'exceptions.TypeError'>: 'NoneType' object is not callable
 > > }}}

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