Noisy exceptions when an outbound federation connection drops

[richvdh]

If the TCP connection is dropped while we are still sending the HTTP request, we get a very shouty exception in the logs:

2018-10-03 21:57:34,069 - twisted - 243 - CRITICAL - - Unexpected exception from twisted.web.client.FileBodyProducer.stopProducing
Capture point (most recent call last):
  File /usr/lib/python3.5/runpy.py, line 184, in _run_module_as_main
    __main__, mod_spec)
  File /usr/lib/python3.5/runpy.py, line 85, in _run_code
    exec(code, run_globals)
  File /opt/synapse/synapse/synapse/app/homeserver.py, line 593, in <module>
    main()
  File /opt/synapse/synapse/synapse/app/homeserver.py, line 589, in main
    run(hs)
  File /opt/synapse/synapse/synapse/app/homeserver.py, line 580, in run
    logger,
  File /opt/synapse/synapse/synapse/app/_base.py, line 117, in start_reactor
    run()
  File /opt/synapse/synapse/synapse/app/_base.py, line 104, in run
    reactor.run()
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/base.py, line 1261, in run
    self.mainLoop()
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/base.py, line 1273, in mainLoop
    self.doIteration(t)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/epollreactor.py, line 235, in doPoll
    log.callWithLogger(selectable, _drdw, selectable, fd, event)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/python/log.py, line 103, in callWithLogger
    return callWithContext({system: lp}, func, *args, **kw)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/python/log.py, line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/python/context.py, line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/python/context.py, line 85, in callWithContext
    return func(*args,**kw)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/posixbase.py, line 627, in _doReadOrWrite
    self._disconnectSelectable(selectable, why, inRead)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/posixbase.py, line 255, in _disconnectSelectable
    selectable.connectionLost(f)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/tcp.py, line 519, in connectionLost
    self._commonConnection.connectionLost(self, reason)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/tcp.py, line 327, in connectionLost
    protocol.connectionLost(reason)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/endpoints.py, line 139, in connectionLost
    return self._wrappedProtocol.connectionLost(reason)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/protocols/tls.py, line 403, in connectionLost
    ProtocolWrapper.connectionLost(self, reason)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/protocols/policies.py, line 125, in connectionLost
    self.wrappedProtocol.connectionLost(reason)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py, line 973, in dispatcher
    return func(*args, **kwargs)
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py, line 1657, in _connectionLost_TRANSMITTING
    self._currentRequest.stopWriting()
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py, line 874, in stopWriting
    _callAppFunction(self.bodyProducer.stopProducing)
Traceback (most recent call last):
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/web/_newclient.py, line 195, in _callAppFunction
    function()
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/web/client.py, line 1087, in stopProducing
    self._task.stop()
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/task.py, line 497, in stop
    self._checkFinish()
  File /opt/synapse/env3/lib/python3.5/site-packages/twisted/internet/task.py, line 507, in _checkFinish
    raise self._completionState
twisted.internet.task.TaskStopped

I think it's harmless, but it's noisy and confusing.

[richvdh]

(on python2 I think we just get the last bit.)

[richvdh]

Note that this is as well as logging the failure as a WARNING:

2018-10-03 21:57:34,068 - synapse.http.matrixfederationclient - 350 - WARNING - federation_transaction_transmission_loop-1625514- {PUT-O-692740} [skaverat.net] Request failed: PUT matrix://skaverat.net/_matrix/federation/v1/send/1538520845391/: RequestTransmissionFailed:[ConnectionLost('Connection lost',)]

[turt2live]

Duplicate of #3838 ?

Edit: Closing #3838 in favour of this one

[richvdh]

yes.

[richvdh]

This looks like it might be https://twistedmatrix.com/trac/ticket/6528, at a glance. There are some suggestions there for workarounds.

[richvdh]

fixed by #4546