exceptions.KeyError: "unable to find reference for name

[Zooko]

I started flogtool tail and it went into the state of "Connecting...". Then I went and started the tahoe node in question, and it started emitting these KeyErrors? at a rate of about 1 Hz. I stopped and restarted the flogtool tail, and here is the first output from it -- the same KeyError?:

zooko@prodhelper2:~/.tahoe$ flogtool tail private/logport.furl
starting..
Connecting..
Connected (to pid 14869)
Remote Versions:
 allmydata: 1.2.0-r3309
 foolscap: 0.3.2
 nevow: 0.9.26
 platform: Linux-Ubuntu_8.04-i686-32bit
 pycryptopp: 0.5.2-1
 pyopenssl: 0.6
 python: 2.5.2
 setuptools: 0.6c8
 simplejson: 1.7.3
 twisted: 2.5.0
 zfec: 1.4.0-4
09:21:03.603 L23 []#4838 an inbound callRemote that we [vq44] executed (on behalf of someone else, TubID v3hb) failed
09:21:03.603 L10 []#4839  reqID=11, rref=<foolscap.broker.Broker object at 0xaf8974c>, methname=RIBroker.getReferenceByName
09:21:03.603 L10 []#4840  args=[]
09:21:03.603 L10 []#4841  kwargs={'name': 'apb7u2eb4s7b55ks2zfl6mdqrmqz2syr'}
09:21:03.603 L10 []#4842  the LOCAL failure was:
 FAILURE:
 [CopiedFailure instance: Traceback from remote host -- Traceback (most recent call last):
   File "/usr/lib/python2.5/site-packages/foolscap/eventual.py", line 26, in _turn
     cb(*args, **kwargs)
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 536, in doNextCall
     d.addCallback(lambda res: self._doCall(delivery))
   File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 191, in addCallback
     callbackKeywords=kw)
   File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 182, in addCallbacks
     self._runCallbacks()
 --- <exception caught here> --- 
   File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 317, in _runCallbacks
     self.result = callback(self.result, *args, **kw)
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 536, in <lambda>
     d.addCallback(lambda res: self._doCall(delivery))
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 571, in _doCall
     return obj.doRemoteCall(delivery.methodname, args, kwargs)
   File "/usr/lib/python2.5/site-packages/foolscap/referenceable.py", line 59, in doRemoteCall
     res = meth(*args, **kwargs) 
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 460, in remote_getReferenceByName
     return self.tub.getReferenceForName(name)
   File "/usr/lib/python2.5/site-packages/foolscap/pb.py", line 742, in getReferenceForName
     raise KeyError("unable to find reference for name '%s'" % (name,))
 exceptions.KeyError: "unable to find reference for name 'apb7u2eb4s7b55ks2zfl6mdqrmqz2syr'"
 ]
09:21:04.107 L20 []#4843 <Listener at 0x8a7280c on 40964 with tubs vq44ojjnmpegwgt745j3f27apbzj65kx> accepting connection from IPv4Address(TCP, '24.155.16.231', 2161)
09:21:04.108 L20 []#4844 Negotiation started
09:21:04.108 L10 []#4845 initServer
09:21:04.379 L10 []#4846 dataReceived(isClient=False,phase=0,options={}): 'GET /id/vq44ojjnmpegwgt745j3f27apbzj65kx HTTP/1.1\r\nHost: 207.7.153.172\r\nUpgrade: TLS/1.0\r\nConnection: Upgrade\r\n\r\n'
09:21:04.380 L10 []#4847 handlePLAINTEXTServer: targetTubID='vq44ojjnmpegwgt745j3f27apbzj65kx'
09:21:04.380 L10 []#4848 handlePLAINTEXTServer: wantEncrypted=True
09:21:04.380 L10 []#4849 startENCRYPTED(isClient=False, encrypted=True)
09:21:04.380 L10 []#4850 startTLS, client=False
09:21:04.380 L10 []#4851 Negotiate.sendHello (isClient=False): {'my-incarnation': 'bc8810ab83d73dc1', 'my-tub-id': 'vq44ojjnmpegwgt745j3f27apbzj65kx', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
09:21:04.798 L23 []#4852 an inbound callRemote that we [vq44] executed (on behalf of someone else, TubID myua) failed
09:21:04.799 L10 []#4853  reqID=4, rref=<foolscap.broker.Broker object at 0xd60accc>, methname=RIBroker.getReferenceByName
09:21:04.799 L10 []#4854  args=[]
09:21:04.799 L10 []#4855  kwargs={'name': 'apb7u2eb4s7b55ks2zfl6mdqrmqz2syr'}
09:21:04.799 L10 []#4856  the LOCAL failure was:
 FAILURE:
 [CopiedFailure instance: Traceback from remote host -- Traceback (most recent call last):
   File "/usr/lib/python2.5/site-packages/foolscap/eventual.py", line 26, in _turn
     cb(*args, **kwargs)
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 536, in doNextCall
     d.addCallback(lambda res: self._doCall(delivery))
   File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 191, in addCallback
     callbackKeywords=kw)
   File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 182, in addCallbacks
     self._runCallbacks()
 --- <exception caught here> --- 
   File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 317, in _runCallbacks
     self.result = callback(self.result, *args, **kw)
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 536, in <lambda>
     d.addCallback(lambda res: self._doCall(delivery))
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 571, in _doCall
     return obj.doRemoteCall(delivery.methodname, args, kwargs)
   File "/usr/lib/python2.5/site-packages/foolscap/referenceable.py", line 59, in doRemoteCall
     res = meth(*args, **kwargs) 
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 460, in remote_getReferenceByName
     return self.tub.getReferenceForName(name)
   File "/usr/lib/python2.5/site-packages/foolscap/pb.py", line 742, in getReferenceForName
     raise KeyError("unable to find reference for name '%s'" % (name,))
 exceptions.KeyError: "unable to find reference for name 'apb7u2eb4s7b55ks2zfl6mdqrmqz2syr'"
 ]
09:21:05.589 L10 []#4857 dataReceived(isClient=False,phase=1,options={}): 'banana-negotiation-range: 3 3\r\ninitial-vocab-table-range: 0 1\r\nlast-connection: none 0\r\nmy-incarnation: c4954c38ed9677fb\r\nmy-tub-id: h6lar3akgqmbaqxpmp5w7qyzmuusngf4\r\n\r\n'  
09:21:05.589 L10 []#4858 evaluateHello(isClient=False): offer={'my-tub-id': 'h6lar3akgqmbaqxpmp5w7qyzmuusngf4', 'last-connection': 'none 0', 'my-incarnation': 'c4954c38ed9677fb', 'initial-vocab-table-range': '0 1', 'banana-negotiation-range': '3 3'}
09:21:05.590 L10 []#4859 iAmTheMaster: True
09:21:05.590 L20 []#4860 Negotiation.sendDecision: {'current-connection': 'bc8810ab83d73dc1 1', 'initial-vocab-table-index': '1 bb33', 'banana-decision-version': '3'}
09:21:05.590 L10 []#4861 Negotiate.switchToBanana(isClient=False)
09:21:05.590 L10 []#4862 params: {'current-seqnum': 1, 'banana-decision-version': 3, 'current-slave-IR': 'c4954c38ed9677fb', 'initial-vocab-table-index': 1}
09:21:05.628 L23 []#4863 an inbound callRemote that we [vq44] executed (on behalf of someone else, TubID gkyx) failed
09:21:05.628 L10 []#4864  reqID=33, rref=<foolscap.broker.Broker object at 0xcd0298c>, methname=RIBroker.getReferenceByName
09:21:05.628 L10 []#4865  args=[]
09:21:05.629 L10 []#4866  kwargs={'name': 'apb7u2eb4s7b55ks2zfl6mdqrmqz2syr'}
09:21:05.629 L10 []#4867  the LOCAL failure was:
 FAILURE:
 [CopiedFailure instance: Traceback from remote host -- Traceback (most recent call last):
   File "/usr/lib/python2.5/site-packages/foolscap/eventual.py", line 26, in _turn
     cb(*args, **kwargs)
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 536, in doNextCall
     d.addCallback(lambda res: self._doCall(delivery))
   File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 191, in addCallback
     callbackKeywords=kw)
   File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 182, in addCallbacks
     self._runCallbacks()
 --- <exception caught here> --- 
   File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 317, in _runCallbacks
     self.result = callback(self.result, *args, **kw)
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 536, in <lambda>
     d.addCallback(lambda res: self._doCall(delivery))
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 571, in _doCall
     return obj.doRemoteCall(delivery.methodname, args, kwargs)
   File "/usr/lib/python2.5/site-packages/foolscap/referenceable.py", line 59, in doRemoteCall
     res = meth(*args, **kwargs) 
   File "/usr/lib/python2.5/site-packages/foolscap/broker.py", line 460, in remote_getReferenceByName
     return self.tub.getReferenceForName(name)
   File "/usr/lib/python2.5/site-packages/foolscap/pb.py", line 742, in getReferenceForName
     raise KeyError("unable to find reference for name '%s'" % (name,))
 exceptions.KeyError: "unable to find reference for name 'apb7u2eb4s7b55ks2zfl6mdqrmqz2syr'"
 ]

[Zooko]

Ah, apb etc. is the swissnum for the storage server that this node itself accidentally ran the first time the node was started, before I remembered to touch no_storage:

zooko@prodhelper2:~/.tahoe$ grep -r apb7u2eb4s7b55ks2zfl6mdqrmqz2syr .
./private/storage.furl:pb://vq44ojjnmpegwgt745j3f27apbzj65kx@207.7.153.172:40964,127.0.0.1:40964/apb7u2eb4s7b55ks2zfl6mdqrmqz2syr

[Zooko]

So this is probably more of a tahoe issue than a foolscap issue...

[Brian Warner]

yeah, it indicates that somebody else (who learned about the storage server, before it was turned off) is trying to connect to you, and failing. They receive a KeyError because your Tub is no longer offering that object. You're seeing this in the logs because Tahoe turns on the log-local-exceptions option. You're seeing them at about 1Hz because there are hundreds of peers who want to connect to that object, and each time you connect to one of them, their Reconnectors seize the opportunity to try to get the reference (along the reverse direction of your outbound TCP connection).

As a Foolscap thing, it might be useful to offer a way to Tahoe developers to say "don't bother logging these sorts of exceptions": that's the purview of #10. It's not clear whether we would want to turn that on or not.. maybe the caller should log it, but the callee should not.

But yes, I think this is a Tahoe thing, not a Foolscap thing. Closing it out..