Unhandled Error: doWrite called on a twisted.internet.udp.Port

[jo-so]

I've saw this message in my error log:

twisted: [] Unhandled Error
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/posixbase.py", line 619, in _doReadOrWrite
    why = selectable.doWrite()
  File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/base.py", line 1192, in doWrite
    "doWrite called on a %s" % reflect.qual(self.__class__))
builtins.RuntimeError: doWrite called on a twisted.internet.udp.Port

Version information

• Version: matrix-synapse-py3 0.99.1.1+stretch1
• Install method: Debian package from matrix.org
• Platform: amd64, Debian stable

[dkowis]

I'm also still seeing this error with 1.1.0

2019-07-05 16:20:43,422 - twisted - 253 - CRITICAL - - Unhandled Error
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/posixbase.py", line 619, in _doReadOrWrite
    why = selectable.doWrite()
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/base.py", line 1197, in doWrite
    "doWrite called on a %s" % reflect.qual(self.__class__))
builtins.RuntimeError: doWrite called on a twisted.internet.udp.Port

[dkowis]

It's also the last thing I see in my logs before my homeserver stops working :( I'm not sure it's related.

[richvdh]

are you using a network log server for your log output?

[dkowis]

Nope. Sent from Nine

…

________________________________ From: Richard van der Hoff <notifications@github.com> Sent: Monday, July 8, 2019 03:14 To: matrix-org/synapse Cc: David Kowis; Comment Subject: Re: [matrix-org/synapse] Unhandled Error: doWrite called on a twisted.internet.udp.Port (#4727) are you using a network log server for your log output? — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

[rubo77]

I have a similar error on synapse 1.20.1:

2020-09-27 20:56:34,573 - twisted - 231 - CRITICAL - - Unhandled Error                                       
Traceback (most recent call last):                                                                    
  File "/home/irc-bridge/synapse/env3.7/lib/python3.7/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)                                            
  File "/home/irc-bridge/synapse/env3.7/lib/python3.7/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)                                              
  File "/home/irc-bridge/synapse/env3.7/lib/python3.7/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)                                                                                                                                                           
  File "/home/irc-bridge/synapse/env3.7/lib/python3.7/site-packages/twisted/python/context.py", line 85, in callWithContext                                                                                                        
    return func(*args,**kw)                                                                                                                                                                                                        
--- <exception caught here> ---                                                                
  File "/home/irc-bridge/synapse/env3.7/lib/python3.7/site-packages/twisted/internet/posixbase.py", line 619, in _doReadOrWrite                                                                                                    
    why = selectable.doWrite()                                                                                                                                                                                                     
  File "/home/irc-bridge/synapse/env3.7/lib/python3.7/site-packages/twisted/internet/base.py", line 1208, in doWrite                                                                                                               
    "doWrite called on a %s" % reflect.qual(self.__class__))                                                                                                                                                                       
builtins.RuntimeError: doWrite called on a twisted.internet.udp.Port    

we have a federation problem between two of our homeservers: If you send from one, it is seen on the other immediately, but vica-versa not. only if you interact with a user from a third server, the message arrive at that later tie then (but with the original timestamp).
could this be related?

[oleg-fiksel]

Similar on Synapse v1.37.1.

Logging configuration:

version: 1

formatters:
  precise:
   format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s- %(message)s'

filters:
  context:
    (): synapse.util.logcontext.LoggingContextFilter
    request: ""

handlers:
  file:
    class: logging.handlers.RotatingFileHandler
    formatter: precise
    filename: /log/homeserver.log
    maxBytes: 104857600
    backupCount: 3
    filters: [context]
    level: WARNING
  console:
    class: logging.StreamHandler
    formatter: precise
    filters: [context]

loggers:
    synapse:
        level: ERROR

    synapse.storage.SQL:
        level: WARNING

root:
    level: ERROR
    handlers: [file, console]

[richvdh]

@oleg-fiksel can you share the stacktrace? A fair bit has changed since 1.20.1.

[oleg-fiksel]

@oleg-fiksel can you share the stacktrace? A fair bit has changed since 1.20.1.

twisted - 258 - CRITICAL - sentinel- Unhandled Error
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/usr/local/lib/python3.8/site-packages/twisted/python/log.py", line 85, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/usr/local/lib/python3.8/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/local/lib/python3.8/site-packages/twisted/python/context.py", line 83, in callWithContext
    return func(*args, **kw)
--- <exception caught here> ---
  File "/usr/local/lib/python3.8/site-packages/twisted/internet/posixbase.py", line 692, in _doReadOrWrite
    why = selectable.doWrite()
  File "/usr/local/lib/python3.8/site-packages/twisted/internet/base.py", line 1349, in doWrite
    raise RuntimeError("doWrite called on a %s" % reflect.qual(self.__class__))
builtins.RuntimeError: doWrite called on a twisted.internet.udp.Port

[richvdh]

I'm at a loss to explain this. It seems to be coming from the depths of Twisted.

[rubo77]

We solved our federation problem by adding a redirect to the .well-known path:

There was a redirect (301) when calling https://matrix.eclabs.de/.well-known/matrix/server – this redirect ended up in nirvana and returned a 404.

We added this to our nginx conf:

    location /.well-known/matrix/server {
      return 200 '{"m.server": "matrix.eclabs.de:443"}';
      add_header Content-Type application/json;
    }

    location /.well-known/matrix/client {
      return 200 '{"m.homeserver": {"base_url": "https://matrix.eclabs.de"}}';
      add_header Content-Type application/json;
      add_header "Access-Control-Allow-Origin" *;
    }

Maybe this was related?

[richvdh]

@rubo77 to be clear: you saw this exception when .well-known/matrix/server returned a 301, and you fixed it by adding the above (to return a 200)? Or the other way around?

I'm struggling to imagine how changing your own .well-known file can fix errors on your own server, but at this point I'm not ruling anything out...

[rubo77]

to be clear: you saw this exception when .well-known/matrix/server returned a 301, and you fixed it by adding the above (to return a 200)?

Exactly

[richvdh]

I'm not able to reproduce it by setting .well-known/matrix/server to be a 301 to a 404 :-S

[erikjohnston]

https://twistedmatrix.com/trac/ticket/4759 looks to be a possibly related ticket with the same stack trace, which suggests the problem might be that we end up doing things with the reactor before daemonizing? I'm not sure though, or how to progress from here

[TheBlueMatt]

Seems to show up on federation_sender workers when they have a lot of work to do (eg new login for a user with many rooms)