search

mumble-voip / mumble-scripts

Mumble scripts is a place for gathering various scripts written for the Mumble VoIP application.
https://www.mumble.info
48 stars 31 forks source link

Client disconnects after ~15s when using LDAPauth #23

Closed Avatat closed 4 years ago

Avatat commented 4 years ago

Hello Mumble Crew! I would love to start using Mumble as VoIP platform for remote working employees in the company where I work, but I have a problem, which is blocking me:

I have a fresh installation of Murmur 1.3.0-1~ppa1~bionic1. When I join the server without any authorization, everything works flawlessly, I can see created channels and I can speak with other users. Murmur log looks as below:

<W>2020-03-11 22:16:02.686 SSL: OpenSSL version is 'OpenSSL 1.1.1  11 Sep 2018'
<W>2020-03-11 22:16:02.686 Initializing settings from /etc/mumble-server.ini (basepath /etc)
<W>2020-03-11 22:16:02.721 MetaParams: TLS cipher preference is "TLS_AES_256_GCM_SHA384:TLS_CHACHA20_POLY1305_SHA256:TLS_AES_128_GCM_SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA:AES256-SHA:AES128-SHA"
<W>2020-03-11 22:16:02.755 ServerDB: Opened SQLite database /var/lib/mumble-server/mumble-server.sqlite
<W>2020-03-11 22:16:02.755 ServerDB: Using SQLite's default rollback journal.
<W>2020-03-11 22:16:02.761 MurmurIce: Endpoint "tcp -h 127.0.0.1 -p 6502 -t 60000" running
<W>2020-03-11 22:16:02.810 Murmur 1.3.0 (1.3.0-1~ppa1~bionic1) running on X11: Ubuntu 18.04.3 LTS: Booting servers
<W>2020-03-11 22:16:02.830 1 => Server listening on 0.0.0.0:64738
<W>2020-03-11 22:16:02.870 1 => Announcing server via bonjour
<W>2020-03-11 22:16:02.883 1 => Not registering server as public

<W>2020-03-11 22:16:17.569 1 => <1:(-1)> New connection: 172.18.0.100:45054
<W>2020-03-11 22:16:17.606 1 => <1:(-1)> Client version 1.3.0 (X11: 1.3.0+dfsg-1)
<W>2020-03-11 22:16:17.616 1 => Starting voice thread
<W>2020-03-11 22:16:17.626 1 => CELT codec switch ffffffff8000000b 0 (prefer ffffffff8000000b) (Opus 1)
<W>2020-03-11 22:16:17.635 1 => <1:bartosz.zieba(-1)> Authenticated

<W>2020-03-11 22:16:27.765 1 => <1:bartosz.zieba(-1)> Connection closed: The remote host closed the connection [1]
<W>2020-03-11 22:16:27.775 1 => Ending voice thread

The problem begins, when I enable LDAPauth.py with this config:

[user]
id_offset       = 1000000000
reject_on_error = True
reject_on_miss  = True
[ice]
host            = 127.0.0.1
port            = 6502
slice           = /usr/share/slice/Murmur.ice
secret          = ICE_SECRET
watchdog        = 30
[ldap]
bind_dn = CN=Mumble,OU=Service,OU=Users,DC=xx,DC=yy,DC=zz
bind_pass = BIND_PASS
ldap_uri = ldap://xx.yy.zz
users_dn = OU=Administrators,OU=Users,DC=xx,DC=yy,DC=zz
discover_dn = false
username_attr = sAMAccountName
number_attr = primaryGroupID
[murmur]
servers      =
[log]
level   =
file    = /var/log/mumble-server/LDAPauth.log
[iceraw]
Ice.ThreadPool.Server.Size = 5

After successfull connection to the server, I see only Root channel, and I see no users (even me). After ~15 seconds, the connection interrupt and the client try to reconnect. Murmur server log:

<W>2020-03-11 22:21:14.652 SSL: OpenSSL version is 'OpenSSL 1.1.1  11 Sep 2018'
<W>2020-03-11 22:21:14.652 Initializing settings from /etc/mumble-server.ini (basepath /etc)
<W>2020-03-11 22:21:14.678 MetaParams: TLS cipher preference is "TLS_AES_256_GCM_SHA384:TLS_CHACHA20_POLY1305_SHA256:TLS_AES_128_GCM_SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA:AES256-SHA:AES128-SHA"
<W>2020-03-11 22:21:14.712 ServerDB: Opened SQLite database /var/lib/mumble-server/mumble-server.sqlite
<W>2020-03-11 22:21:14.712 ServerDB: Using SQLite's default rollback journal.
<W>2020-03-11 22:21:14.718 MurmurIce: Endpoint "tcp -h 127.0.0.1 -p 6502 -t 60000" running
<W>2020-03-11 22:21:14.760 Murmur 1.3.0 (1.3.0-1~ppa1~bionic1) running on X11: Ubuntu 18.04.3 LTS: Booting servers
<W>2020-03-11 22:21:14.780 1 => Server listening on 0.0.0.0:64738
<W>2020-03-11 22:21:14.821 1 => Announcing server via bonjour
<W>2020-03-11 22:21:14.833 1 => Not registering server as public

<W>2020-03-11 22:21:29.245 Added Ice MetaCallback 270C2A11-9BBD-4CDD-9E1D-0002D3CE1413 -o -e 1.0:tcp -h 127.0.0.1 -p 40283 -t 5000
<W>2020-03-11 22:21:29.256 1 => Set Ice Authenticator to B06E683D-F47F-4F7C-94D9-6FA0375C1413 -t -e 1.0:tcp -h 127.0.0.1 -p 40283 -t 5000
<W>2020-03-11 22:21:29.266 1 => Set Ice UpdatingAuthenticator to B06E683D-F47F-4F7C-94D9-6FA0375C1413 -t -e 1.0:tcp -h 127.0.0.1 -p 40283 -t 5000

<W>2020-03-11 22:21:37.378 1 => <1:(-1)> New connection: 172.18.0.100:45098
<W>2020-03-11 22:21:37.420 1 => <1:(-1)> Client version 1.3.0 (X11: 1.3.0+dfsg-1)

LDAPauth log:

2020-03-11 22:21:29,239 INFO Starting LDAP mumble authenticator
2020-03-11 22:21:29,241 DEBUG Using shared ice secret
2020-03-11 22:21:29,242 INFO Connecting to Ice server (127.0.0.1:6502)
2020-03-11 22:21:29,244 INFO Attaching meta callback
2020-03-11 22:21:29,246 INFO Setting authenticator for virtual server 1
2020-03-11 22:21:29,267 INFO Attaching meta callback
2020-03-11 22:21:29,267 INFO Setting authenticator for virtual server 1
2020-03-11 22:21:37,421 DEBUG try to connect to ldap (bind_dn will be used)
2020-03-11 22:21:37,424 DEBUG User match found, display "Bartosz Zięba" with UID 513
2020-03-11 22:21:37,424 DEBUG Checking group membership for bartosz.zieba
2020-03-11 22:23:48,424 CRITICAL Unexpected exception caught
2020-03-11 22:23:48,424 ERROR {'info': u'Referral:\nldap://example.org/ou=Groups,dc=example,dc=org', 'errno': 107, 'desc': u'Referral'}
Traceback (most recent call last):
  File "/usr/local/sbin/LDAPauth.py", line 356, in newfunc
    return func(*args, **kws)
  File "/usr/local/sbin/LDAPauth.py", line 340, in newfunc
    return func(*args, **kws)
  File "/usr/local/sbin/LDAPauth.py", line 526, in authenticate
    res = ldap_conn.search_s(cfg.ldap.group_dn, ldap.SCOPE_SUBTREE, '(%s=%s)' % (cfg.ldap.group_attr, user_dn), [cfg.ldap.number_attr, cfg.ldap.display_attr])
  File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 852, in search_s
    return self.search_ext_s(base,scope,filterstr,attrlist,attrsonly,None,None,timeout=self.timeout)
  File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 846, in search_ext_s
    return self.result(msgid,all=1,timeout=timeout)[1]
  File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 738, in result
    resp_type, resp_data, resp_msgid = self.result2(msgid,all,timeout)
  File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 742, in result2
    resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all,timeout)
  File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 749, in result3
    resp_ctrl_classes=resp_ctrl_classes
  File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 756, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 329, in _ldap_call
    reraise(exc_type, exc_value, exc_traceback)
  File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 313, in _ldap_call
    result = func(*args,**kwargs)
REFERRAL: {'info': u'Referral:\nldap://example.org/ou=Groups,dc=example,dc=org', 'errno': 107, 'desc': u'Referral'}

Mumble client log:

[23:21:37] Connected.
[23:21:52] Server connection failed: Server is not responding to TCP pings.
[23:22:02] Reconnecting

As you can see, the server log ends differently than in the previous case (without LDAPauth), there is no Starting voice thread and later lines.

How can I dig it deeper? If the patch is needed, I would like to contribute and help the project, but I don't know where to start.

Avatat commented 4 years ago

Problem solved. I will write a full solution soon!

Avatat commented 4 years ago

LDAPauth was always hanging at DEBUG Checking group membership for bartosz.zieba I sniffed LDAP communication and it looked like below:

No. Protocol    Length  Info
78  LDAP    155 bindRequest(1) "CN=Mumble,OU=Service,OU=Users,DC=xx,DC=yy,DC=zz" simple 
79  LDAP    78  bindResponse(1) success 
81  LDAP    203 searchRequest(2) "OU=Administrators,OU=Users,DC=xx,DC=yy,DC=zz" wholeSubtree 
82  LDAP    250 searchResEntry(2) "CN=Bartosz Zięba,OU=Administrators,OU=Users,DC=xx,DC=yy,DC=zz"  | searchResDone(2) success  [1 result]
83  LDAP    227 searchRequest(3) "ou=Groups,dc=example,dc=org" wholeSubtree 
84  LDAP    212 searchResDone(3) referral (0000202B: RefErr: DSID-03100835, data 0, 1 access points\n\tref 1: 'example.org'\n)  [1 result]

I started wondering, what is ou=Groups,dc=example,dc=org, and why LDAPauth is asking for it. The answer was in LDAPauth.py:

default = { ...
                    ('group_dn', str, 'ou=Groups,dc=example,dc=org'),
                    ... }

So, I set group_dn to CN=Mumble Users,OU=Apps,OU=Groups,DC=xx,DC=yy,DC=zz, and LDAPauth started going further with LDAP communication:

No. Protocol    Length  Info
44  LDAP    155 bindRequest(1) "CN=Mumble,OU=Service,OU=Users,DC=xx,DC=yy,DC=zz" simple 
45  LDAP    78  bindResponse(1) success 
47  LDAP    199 searchRequest(2) "OU=Administrators,OU=Users,DC=xx,DC=yy,DC=zz" wholeSubtree 
48  LDAP    248 searchResEntry(2) "CN=Bartosz Zięba,OU=Administrators,OU=Users,DC=xx,DC=yy,DC=zz"  | searchResDone(2) success  [2 results]
49  LDAP    260 searchRequest(3) "CN=Mumble Users,OU=Apps,OU=Groups,DC=xx,DC=yy,DC=zz" wholeSubtree 
50  LDAP    196 searchResEntry(3) "CN=Mumble Users,OU=Apps,OU=Groups,DC=xx,DC=yy,DC=zz"  | searchResDone(3) success  [2 results]
51  LDAP    158 bindRequest(4) "CN=Bartosz Zięba,OU=Administrators,DC=xx,DC=yy,DC=zz" simple 
52  LDAP    78  bindResponse(4) success

Success! All of our users could securely connect to the new Mumble server using their LDAP credentials. Mumble stays private and secured.