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

Fri Sep 2 22:58:20 UTC 2011

#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):

 I noticed this comment in TorCtl.py:

 # eventThread provides a more reliable indication of when we are done.
 # The _loop thread won't always die when self.close() is called.

 ah.

 I removed the call to call self._thread.join(), where _thread is the _loop
 thread. I'm not sure if this will have any other side effects.

 Replying to [comment:21 aagbsn]:
 > Clarification: the scanner freezes after this Traceback and the child
 process does not exit.
 >
 > Replying to [comment:20 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:23>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online