Ticket #55 (closed defect: fixed)

Opened 10 months ago

Last modified 5 months ago

log_gatherer.furl can be used too early

Reported by: warner Assigned to:
Priority: major Milestone: 0.3.0
Component: logging Version: 0.2.4
Keywords: Cc:

Description

I observed a traceback in Tahoe as it started up.. it looks like it managed to connect to the log gatherer (running on the same host) extremely quickly, before the Tahoe node had managed to do a Tub.setLocation. As a result, the getLogPortFURL call failed, and the node never gave its logport to the introducer: 

  File "/usr/lib/python2.5/site-packages/foolscap/reconnector.py", line 95, in _connected
    cb(rref, *args, **kwargs)
  File "/usr/lib/python2.5/site-packages/foolscap/pb.py", line 376, in _log_gatherer_connected
    ignored = self.getLogPortFURL()
  File "/usr/lib/python2.5/site-packages/foolscap/pb.py", line 410, in getLogPortFURL
    furlFile=furlfile)
  File "/usr/lib/python2.5/site-packages/foolscap/pb.py", line 660, in registerReference
    raise RuntimeError("you must setLocation() before "
exceptions.RuntimeError: you must setLocation() before you can registerReference()

One event later, Tub.setLocation was called.

I think this is partly the result of Tahoe's setup sequence: in Node.init it creates the Tub, setServiceParent's it to the node, then does the setOption that triggers the use of log_gatherer.furl . This results in the gatherer code doing Tub.connectTo before Tub.startService is even called.

Once startService happens, the connection occurs quickly. Here are a few lines of the trace: 

# 18:59:05 0.7869 [0]: UNUSUAL Tub.connectTo((log-gatherer.furl)) queued until Tub.startService called
# 18:59:06 0.4523 [8]: Node.startService
# 18:59:06 0.4527 [9]: Node._startService
# 18:59:06 0.4645 [12]: TubConnector created from ... to log-gatherer..
# [52]: duplicate connection closed
# [64]: negotiationComplete
# [67]: the exception shown above
# [68]: Tub location set

(some events are missing, this trace was gathered half an hour afterwards using flogtool tail --catch-up).

I need to examine the sequencing and figure out how the connection managed to complete before the setLocation was called. It might be a good idea to stall the gatherer connection until.. what, after setLocation happens? If it ever happens?

Change History

04/30/08 17:47:55 changed by warner

rob hit a similar problem: same traceback. I'm not sure what his startup code looked like, though. He told me that he used setLocationAutomatically, but waited until its Deferred had fired before calling the setOption that established the log-gatherer furl.

07/29/08 19:47:30 changed by warner

  • status changed from new to closed.
  • resolution set to fixed.
  • milestone changed from undecided to 0.3.0.

Found it. The problem can be fixed by deferring the connection to the log gatherer until after setLocation has been called. I had avoided this because I didn't want to make setLocation obligatory, but the code implicitly enforces this restriction already. So the fix is to make the restriction explicit, and then wait on the log gatherer connectTo call. Fixed by [438:efbce2e2b47a].