Good morning,
we’re testing privacyIDEA in our environment.
After a random time (2/3 days), the 2FA stops working.
It seems that it can’t contact LDAP server no more.
We’ve checked the number of sockets to LDAP opened by privacyIDEA, and they are more than 1000.
If we restart the service (systemctl restart uwsgi.service) the problem is temporarily solved: 2FA works again.
But the number of sockets to LDAP opened constantly increases, and when it reaches 1000 (circa) the problem appears again.
privacyIDEA is installed in an Ubuntu Linux virtual machine:
Linux Ubuntu 22.04 LTS
privacyidea 3.9-1jammy (ubuntu package)
privacyidea-nginx 3.9.1-1jammy (ubuntu package)
privacyidea-radius 3.4.2-1jammy (ubuntu package)
These are the settings:
cat /etc/uwsgi/apps-enabled/privacyidea.xml
python3
/run/uwsgi/app/privacyidea/privacyidea.socket
/etc/privacyidea/
/opt/privacyidea/
privacyideaapp
4
60
8
1
/tmp/stats.socket
2000
8192
1024
368
192
privacyidea
www-data
Config LDAP:
Resolver Configuration
ldapreplica
* Name of the resolver: ldapreplica
* Type of the resolver: ldapresolver
Configuration
.............
AUTHTYPE: **Simple**
BINDDN: **cn=USER,dc=SYS,dc=CC**
BINDPW: **XXXXXX**
CACHE_TIMEOUT: **120**
EDITABLE: **False**
LDAPBASE: **dc=SYS,dc=CC**
LDAPSEARCHFILTER: **(uid=*)(serviceEnabled=vpn)(objectClass=inetOrgPerson)**
LDAPURI: **ldap://ldap.address.cc**
LOGINNAMEATTRIBUTE: **uid**
MULTIVALUEATTRIBUTES: **["email", "roles", "group"]**
NOREFERRALS: **True**
NOSCHEMAS: **True**
SCOPE: **SUBTREE**
SERVERPOOL_PERSISTENT: **True**
SERVERPOOL_ROUNDS: **2**
SERVERPOOL_SKIP: **30**
SERVERPOOL_STRATEGY: **ROUND_ROBIN**
SIZELIMIT: **500**
START_TLS: **True**
TIMEOUT: **5**
TLS_VERIFY: **False**
TLS_VERSION: **5**
UIDTYPE: **entryUUID**
USERINFO: **{ "email" : "mail", "surname" : "sn", "givenname" : "givenName", "roles" : "roles", "group" : "serviceEnabled" }**
Example of Error on radius log:
2023-12-12 20:31:36 auth USER=YYYYYYY ORG= CSI=5.90.XXX NAS=XXX CUI=Unknown MSGRep=500 Internal Server Error: The server encountered an internal error and was unable to complete your request. Either the server is overloaded or there is an error in the application. HG=VPN ModuleMSG=NONE RESULT=FAIL
2023-11-27 15:55:17 auth USER=XXXXXXX ORG= CSI=IPADDR NAS=IPADDR CUI=Unknown MSGRep=500 Internal Server Error: The server encountered an internal error and was unable to complete your request. Either the server is overloaded or there is an error in the application. HG=VPN ModuleMSG=NONE RESULT=FAIL
privacyidea access.log
127.0.0.1 - - [12/Dec/2023:20:31:41 +0000] "POST /validate/check HTTP/1.1" 500 896 "-" "FreeRADIUS"
127.0.0.1 - - [27/Nov/2023:15:55:22 +0000] "POST /validate/check HTTP/1.1" 500 897 "-" "FreeRADIUS"
ON PI SERVER, we check the number of connections opened by privacyIDEA:
# while true ; do (echo -n "`date +"%Y%m%d-%H%MUTC"`: " && ps -fu privacyidea | grep privacy | tr -s ' ' | cut -d\ -f 2 | awk '{system("ls -l /proc/" $1 "/fd | grep socket ")}' | wc -l ) >> check.log; sleep 300; done
# cat /var/log/privacyidea/check.log
20231201-1313UTC: 31
20231201-1318UTC: 34
20231201-1323UTC: 37
20231201-1328UTC: 39
20231201-1333UTC: 42
20231201-1338UTC: 47
20231201-1343UTC: 50
... OMISSIS ...
20231204-1249UTC: 1031
20231204-1254UTC: 1032
20231204-1259UTC: 1032
20231204-1304UTC: 1032
20231204-1309UTC: 1032
20231204-1314UTC: 1032
20231204-1319UTC: 1033
20231204-1324UTC: 1033
20231204-1329UTC: 1033
ON LDAP SERVER
tcp 0 0 IP_ADDR_LDAP:389 IP_ADDR_PI:36891 ESTABLISHED
tcp 0 0 IP_ADDR_LDAP:389 IP_ADDR_PI:51639 ESTABLISHED
tcp 0 0 IP_ADDR_LDAP:389 IP_ADDR_PI:54253 ESTABLISHED
tcp 0 0 IP_ADDR_LDAP:389 IP_ADDR_PI:33399 ESTABLISHED
tcp 0 0 IP_ADDR_LDAP:389 IP_ADDR_PI:33873 ESTABLISHED
tcp 0 0 IP_ADDR_LDAP:389 IP_ADDR_PI:41223 ESTABLISHED
# netstat -na | grep "IP_Server_PI:" | wc -l
903
#
Example of error log from privacyidea.log
[2023-12-12 20:31:41,896][799916][140018760190912][ERROR][privacyidea.app:1891] Exception on /validate/check [POST]
Traceback (most recent call last):
File "/opt/privacyidea/lib/python3.10/site-packages/ldap3/strategy/sync.py", line 82, in receiving
data = self.connection.socket.recv(self.socket_size)
TimeoutError: timed out
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/opt/privacyidea/lib/python3.10/site-packages/flask/app.py", line 2447, in wsgi_app
response = self.full_dispatch_request()
File "/opt/privacyidea/lib/python3.10/site-packages/flask/app.py", line 1952, in full_dispatch_request
rv = self.handle_user_exception(e)
File "/opt/privacyidea/lib/python3.10/site-packages/flask/app.py", line 1821, in handle_user_exception
reraise(exc_type, exc_value, tb)
File "/opt/privacyidea/lib/python3.10/site-packages/flask/_compat.py", line 39, in reraise
raise value
File "/opt/privacyidea/lib/python3.10/site-packages/flask/app.py", line 1948, in full_dispatch_request
rv = self.preprocess_request()
File "/opt/privacyidea/lib/python3.10/site-packages/flask/app.py", line 2242, in preprocess_request
rv = func()
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/api/validate.py", line 134, in before_request
request.User = get_user_from_param(request.all_data)
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/log.py", line 146, in log_wrapper
return func(*args, **kwds)
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/user.py", line 658, in get_user_from_param
user_object = User(login=username, realm=realm,
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/log.py", line 146, in log_wrapper
return func(*args, **kwds)
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/user.py", line 103, in __init__
self._get_user_from_userstore()
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/usercache.py", line 63, in cache_wrapper
return wrapped_function(*args, **kwds)
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/user.py", line 113, in _get_user_from_userstore
self._get_resolvers()
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/user.py", line 238, in _get_resolvers
if self._locate_user_in_resolver(resolvername):
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/user.py", line 258, in _locate_user_in_resolver
uid = y.getUserId(self.login)
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/resolvers/LDAPIdResolver.py", line 276, in cache_wrapper
f_result = func(self, *args, **kwds)
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/resolvers/LDAPIdResolver.py", line 656, in getUserId
self._bind()
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/resolvers/LDAPIdResolver.py", line 523, in _bind
self.l = self.create_connection(authtype=self.authtype,
File "/opt/privacyidea/lib/python3.10/site-packages/privacyidea/lib/resolvers/LDAPIdResolver.py", line 1360, in create_connection
r = l.start_tls(read_server_info=False)
File "/opt/privacyidea/lib/python3.10/site-packages/ldap3/core/connection.py", line 1307, in start_tls
if self.server.tls.start_tls(self) and self.strategy.sync: # for asynchronous connections _start_tls is run by the strategy
File "/opt/privacyidea/lib/python3.10/site-packages/ldap3/core/tls.py", line 259, in start_tls
result = connection.extended('1.3.6.1.4.1.1466.20037')
File "/opt/privacyidea/lib/python3.10/site-packages/ldap3/core/connection.py", line 1268, in extended
response = self.post_send_single_response(self.send('extendedReq', request, controls))
File "/opt/privacyidea/lib/python3.10/site-packages/ldap3/strategy/sync.py", line 121, in post_send_single_response
responses, result = self.get_response(message_id)
File "/opt/privacyidea/lib/python3.10/site-packages/ldap3/strategy/base.py", line 354, in get_response
responses = self._get_response(message_id, timeout)
File "/opt/privacyidea/lib/python3.10/site-packages/ldap3/strategy/sync.py", line 157, in _get_response
responses = self.receiving()
File "/opt/privacyidea/lib/python3.10/site-packages/ldap3/strategy/sync.py", line 92, in receiving
raise communication_exception_factory(LDAPSocketReceiveError, type(e)(str(e)))(self.connection.last_error)
ldap3.core.exceptions.LDAPSocketReceiveError: error receiving data: timed out
[2023-12-12 20:33:28,765][799915][140018760190912][INFO][privacyidea.lib.resolvers.LDAPIdResolver:332] Setting system wide POOLING_LOOP_TIMEOUT to 10.