Synapse: internal users authentication broken when ldap in use

[4nd3r]

i'm using both external ldap and internal synapse database for authentication.

after upgrading to 0.33.9 internal users can't login anymore.

using debian stretch and packages from https://matrix.org/packages/debian/.

2018-11-21 15:09:08,845 - synapse.http.server - 112 - ERROR - - Failed handle request via <function _async_render at 0x7f9d35db2ed8>: <XForwardedForRequest at 0x7f9d084c01b8 method=u'POST' uri=u'/_matrix/client/r0/login' clientproto=u'HTTP/1.0' site=8008>: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 653, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1442, in gotResult
    _inlineCallbacks(r, g, deferred)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
--- <exception caught here> ---
  File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 81, in wrapped_request_handler
    yield h(self, request)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/synapse/http/server.py", line 316, in _async_render
    callback_return = yield callback(request, **kwargs)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/synapse/rest/client/v1/login.py", line 150, in on_POST
    result = yield self._do_other_login(login_submission)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/synapse/rest/client/v1/login.py", line 226, in _do_other_login
    login_submission,
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/synapse/handlers/auth.py", line 709, in validate_login
    qualified_user_id, password,
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 422, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/synapse/handlers/auth.py", line 743, in _check_local_password
    result = yield self.validate_hash(password, password_hash)
  File "/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 250, in inContext
    result = inContext.theWork()
  File "/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 266, in <lambda>
    inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
  File "/usr/lib/python2.7/dist-packages/synapse/util/logcontext.py", line 633, in g
    return f(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/synapse/util/logcontext.py", line 289, in __exit__
    self.parent_context._resource_usage += self._resource_usage
exceptions.AttributeError: 'Sentinel' object has no attribute '_resource_usage'

[4nd3r]

@richvdh guessed correctly: PR https://github.com/matrix-org/synapse/pull/4074 caused this

[cuibonobo]

I was able to fix this issue by adding an attribute check on line 288 of synapse/util/logcontext.py. From this:
https://github.com/matrix-org/synapse/blob/678ad155a2eecc344d93c6849f7bd887bcc42191/synapse/util/logcontext.py#L288

to this:

if self.parent_context is not None and hasattr(self.parent_context, '_resource_usage'):

I thought of making a PR for this but I was afraid the root cause of the problem was more complex.

[richvdh]

@cuibonobo I think that's an entirely valid workaround. I'd accept a PR that did that.

The root of the issue is that the ldap code is not correctly preserving the log context, so when we come back to the password check code, there is no active log context. So the correct solution is to find out where the ldap code is dropping the logcontext, and fix that. Doing so will then make sure that CPU used by /login requests (which can be very significant) is correctly attributed to the requests that cause them.

The ldap code looks to be calling twisted.internet.threads.deferToThread - this will indeed leak the logcontext. synapse.util.logcontext.defer_to_thread should be a drop-in replacement which will correctly preserve the logcontext.

However, that could get fiddly, and making line 288 more robust wouldn't be a bad thing anyway.

[xoxys]

@richvdh What is the status? Is there already a pull request or the issue fixed in another form? The main problem for me is, that I don't found a way to make a ldap user to an admin user so the admin user rely on a working ldap and local auth in parallel.

[xperimental]

FWIW: I am sorry for the commit message related spam in this issue.

[richvdh]

fixed by #4486, hopefully