389-users October 2024

389-users@lists.fedoraproject.org

7 participants
9 discussions

high 'wtime' with 2.4.5
by John Thurston 06 Dec '24

06 Dec '24

I have a new instance of 2.4.5, on which I'm seeing a very high* 'wtime' in the access log. From https://www.port389.org/docs/389ds/design/access-log-new-time-stats-design.… I read > * *wtime* - This is the amount of time the operation was waiting in > the work queue before being picked up by a worker thread. > Is this still an accurate description of 'wtime' ? If true, I suspect the high values I'm seeing have nothing to do with the version of the software I'm running, and everything to do with the system on which the software is running. Work has arrived, and been queued, but there aren't enough worker-threads to keep the queue serviced in a timely manner. * 'high' as in 3,000% longer than what I see on a totally different system running 1.4.4 -- -- Do things because you should, not just because you can. John Thurston 907-465-8591 John.Thurston(a)alaska.gov Department of Administration State of Alaska

2 4

Using modifyTimeStamp in queries
by tdarby＠arizona.edu 01 Nov '24

01 Nov '24

We have an application that needs to query for and return thousands of entries with modifyTimeStamp greater than a given time. This is turning out to be too slow for this app and so I'm wondering if there's any way to speed this up other than throwing more CPU at it. Tim Darby

3 3

Issue with multiple replication happening at once
by Jason Villarroel 25 Oct '24

25 Oct '24

Hello, We're experiencing an issue with multiple replications happening at once to a consumer/supplier causing the ldap service to crash with the ldap error DB candidate list and an error code. This seems to happen more with a larger database that is over 1.2 million records. When additional resources are added it happens less frequently. Error logs: [25/Oct/2024:08:52:14.538763222 -0400] - WARN - keys2idl - received NULL idl from index_read_ext_allids, treating as empty set [25/Oct/2024:08:52:14.811103867 -0400] - WARN - keys2idl - this is probably a bug that should be reported [25/Oct/2024:08:52:14.850394414 -0400] - ERR - build_candidate_list - Database error -12795 [25/Oct/2024:08:52:15.695865951 -0400] - WARN - keys2idl - received NULL idl from index_read_ext_allids, treating as empty set [25/Oct/2024:08:52:15.704753033 -0400] - WARN - keys2idl - this is probably a bug that should be reported [25/Oct/2024:08:52:15.712729986 -0400] - ERR - build_candidate_list - Database error -12795 [25/Oct/2024:08:52:16.495910299 -0400] - WARN - keys2idl - received NULL idl from index_read_ext_allids, treating as empty set [25/Oct/2024:08:52:16.606692166 -0400] - WARN - keys2idl - this is probably a bug that should be reported [25/Oct/2024:08:52:16.614021976 -0400] - ERR - build_candidate_list - Database error -12795 Jason Villarroel Systems Administrator Florida International University Division of Information Technology – Enterprise Systems PC 120 305-348-2687 (Office) 305-348-3686 (Fax) [cid:12dca963-04c7-4961-bd76-9d04fc212777]<https://fiu.service-now.com/sp?id=kb_article&sys_id=dd81ca14db54fa4019f1739…> Division of Information Technology staff will never ask for your password. Never email your password or share confidential information in emails.

1 0

Re: Inconsistent Ldap connection issues
by Thierry Bordaz 16 Oct '24

16 Oct '24

Hi Gary, I meant that the access logs covered 5hours. It would be helpful to capture/focus on the logs from the few minutes before/after the time when the problem occurred. Then check from those limited logs if there is a pattern or unexpected events (long operation, no operation, abandon, ...) best regards thierry On 10/7/24 7:37 PM, Gary Waters wrote: > > Hi Thierry, > > Ok I ll decrease the timeout to 15 seconds then. > >> Reducing the size of the logs will help. > Which log and how do I do this ? > > Thanks Marc and Theirry! > > -Gary > > On 10/7/24 00:26, Thierry Bordaz wrote: >> >> Hi, >> >> Those slap_poll error means that the server was unable to send back >> PDU to the client. It can occur if the client sends a request and >> does not read fast enough the results. The timeout is high 30s >> (30000), could it be that the problem is on the client side (app) ? >> >> I suggest that you focus on the timestamp when the application >> reports a failure. Then look in the access/error logs from 1-3min >> before and after the time of the failure. Logconv from that limited >> scope will be more helpful than a global one. >> >> The pattern looks to be an app opens a connection, switch to secure >> connection (start-tls), issue 6-8 SRCH then close. etime/wtime/optime >> looks fine but as it is an average (over 1M op) it is not helpful. >> Reducing the size of the logs will help. >> I found interesting the abandon op as it is possibly related to a >> performance issue. >> >> best regards >> thierry >> >> >> On 10/4/24 11:54 PM, Gary Waters via 389-users wrote: >>> >>> Hi Marc, >>> >>> I have made nsslapd-listen-backlog-size to 512. >>> >>> For the ioblocktimeout, I increased it because of an error I was seeing: >>> >>> [30/Sep/2024:16:26:55.987681019 -0700] - ERR - slapd_poll - (743) - >>> Timed out >>> [30/Sep/2024:16:34:49.646922635 -0700] - ERR - slapd_poll - (568) - >>> Timed out >>> >>> Googling stated that I should increase the ioblocktimeout. So I >>> bumped it up from 20000 to 30000. >>> >>> Since then, those slapd_poll timed out errors have not occurred. >>> Should I have changed something else? >>> >>> What should I increase these to? >>> >>> net.core.somaxconn = 4096 >>> net.ipv4.tcp_max_syn_backlog = 4096 >>> >>> Thanks so much for your help! >>> >>> -Gary >>> >>> On 10/4/24 11:55, Marc Sauton wrote: >>>> tune up nsslapd-listen-backlog-size >>>> and verify the net.core.somaxconn and net.ipv4.tcp_max_syn_backlog >>>> are high enough ( sysctl -a ) >>>> possibly tune down the nsslapd-ioblocktimeout value >>>> Thanks, >>>> M. >>>> >>>> On Fri, Oct 4, 2024 at 11:06 AM gwaters-web--- via 389-users >>>> <389-users(a)lists.fedoraproject.org> wrote: >>>> >>>> Hello, >>>> >>>> We are experiencing a new issue since we upgraded from >>>> 389-ds-base from >>>> 1.4~ish to 2.0.15 on RHEL 8. I couldnt figure how to fix it, so I >>>> switched to RHEL9 and are on 2.4.5-9. >>>> >>>> The issue is during a performance load test of a web >>>> application. The >>>> app logs into a website and does some things that searches >>>> against ldap, >>>> and does some transactions. This app has been performing fine >>>> for years, >>>> the app has changed so it could be something there, but I am >>>> not sure >>>> about that because of the percentage of the traffic that is >>>> successful. >>>> >>>> The errors for the web app are "Can't contact Ldap Server" and >>>> sometimes >>>> "Can't contact LDAP server. Start TLS request accepted.Server >>>> willing to >>>> negotiate SSL. (0xFFFF [-1])". Out of the 128k connections >>>> below, these >>>> errors will happen like 5 or 6 times, so its wildly >>>> inconsistent and random. >>>> >>>> I did a logconv analysis with 6 hours of a day of testing, see >>>> below. >>>> One thing that really stood out to me was the peak concurrent >>>> connections = 22.. That peak is so low, I dont know how these >>>> errors are >>>> happening. >>>> >>>> I dont see any errors in the access log ( grepping for err=1). >>>> I looked for cache warnings/errors in the access/errors logs, >>>> but didnt >>>> find any. I dont see things like unavailable connections in the >>>> access logs. >>>> >>>> Suggestions on what to change or look for in the logs ? >>>> >>>> Thanks, >>>> Gary >>>> >>>> >>>> information: >>>> Machine Size: 16G of ram, 4 core AMD (its an EC2.m5.large, gp3 >>>> disk type) >>>> >>>> kernel: >>>> Linux 5.14.0-427.35.1.el9_4.x86_64 #1 SMP PREEMPT_DYNAMIC >>>> packages: >>>> 389-ds-base-libs-2.4.5-9.el9_4.x86_64 >>>> 389-ds-base-2.4.5-9.el9_4.x86_64 >>>> >>>> single instance of dirsrv running >>>> dirsrv modifcations from default: >>>> >>>> nsslapd-logging-backend: dirsrv-log,syslog >>>> nsslapd-maxdescriptors: 8192 >>>> nsslapd-listen-backlog-size: 256 >>>> nsslapd-allow-hashed-passwords: on >>>> nsslapd-idletimeout: 30 >>>> nsslapd-ioblocktimeout: 30000 >>>> nsslapd-sizelimit: -1 >>>> nsslapd-auditlog-logging-enabled: off >>>> nsslapd-lookthroughlimit: -1 >>>> >>>> dirsrv.systemd: >>>> limitNOFILE=8192 >>>> >>>> >Total Log Lines Analszed: 2694287 >>>> > >>>> > >>>> > >>>> > ---------- Access Log Output ------------ >>>> > >>>> > Start of Logs: 26/Sep/2024:10:07:32.089983378 >>>> > End of Logs: 26/Sep/2024:15:54:29.895403688 >>>> > >>>> > Processed Log Time: 5 Hours, 46 Minutes, 57.805426688 Seconds >>>> > >>>> > Restarts: 0 >>>> > Secure Protocol Versions: >>>> > - TLS1.2 128-bit AES-GCM (123117 connections) >>>> > >>>> > Peak Concurrent Connections: 22 >>>> > Total Operations: 1097043 >>>> > Total Results: 1097044 >>>> > Overall Performance: 100.0% >>>> > >>>> > Total Connections: 128646 (6.18/sec) (370.78/min) >>>> > - LDAP Connections: 128646 (6.18/sec) (370.78/min) >>>> > - LDAPI Connections: 0 (0.00/sec) (0.00/min) >>>> > - LDAPS Connections: 0 (0.00/sec) (0.00/min) >>>> > - StartTLS Extended Ops: 123116 (5.91/sec) (354.84/min) >>>> > >>>> > Searches: 845279 (40.60/sec) (2436.22/min) >>>> > Modifications: 0 (0.00/sec) (0.00/min) >>>> > Adds: 0 (0.00/sec) (0.00/min) >>>> > Deletes: 0 (0.00/sec) (0.00/min) >>>> > Mod RDNs: 0 (0.00/sec) (0.00/min) >>>> > Compares: 0 (0.00/sec) (0.00/min) >>>> > Binds: 128647 (6.18/sec) (370.78/min) >>>> > >>>> > Average wtime (wait time): 0.001560856 >>>> > Average optime (op time): 0.003310453 >>>> > Average etime (elapsed time): 0.004868040 >>>> > >>>> > Multi-factor Authentications: 0 >>>> > Proxied Auth Operations: 0 >>>> > Persistent Searches: 0 >>>> > Internal Operations: 0 >>>> > Entry Operations: 0 >>>> > Extended Operations: 123116 >>>> > Abandoned Requests: 1 >>>> > Smart Referrals Received: 0 >>>> > >>>> > VLV Operations: 0 >>>> > VLV Unindexed Searches: 0 >>>> > VLV Unindexed Components: 0 >>>> > SORT Operations: 0 >>>> > >>>> > Entire Search Base Queries: 0 >>>> > Paged Searches: 0 >>>> > Unindexed Searches: 0 >>>> > Unindexed Components: 0 >>>> > Invalid Attribute Filters: 0 >>>> > FDs Taken: 128646 >>>> > FDs Returned: 129318 >>>> > Highest FD Taken: 968 >>>> > >>>> > Broken Pipes: 0 >>>> > Connections Reset By Peer: 0 >>>> > Resource Unavailable: 0 >>>> > Max BER Size Exceeded: 0 >>>> > >>>> > Binds: 128647 >>>> > Unbinds: 119206 >>>> > ------------------------------------- >>>> > - LDAP v2 Binds: 0 >>>> > - LDAP v3 Binds: 128647 >>>> > - AUTOBINDs(LDAPI): 0 >>>> > - SSL Client Binds: 0 >>>> > - Failed SSL Client Binds: 0 >>>> > - SASL Binds: 0 >>>> > - Dir >>>> >>>> -- >>>> _______________________________________________ >>>> 389-users mailing list -- 389-users(a)lists.fedoraproject.org >>>> To unsubscribe send an email to >>>> 389-users-leave(a)lists.fedoraproject.org >>>> Fedora Code of Conduct: >>>> https://docs.fedoraproject.org/en-US/project/code-of-conduct/ >>>> List Guidelines: >>>> https://fedoraproject.org/wiki/Mailing_list_guidelines >>>> List Archives: >>>> https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject… >>>> Do not reply to spam, report it: >>>> https://pagure.io/fedora-infrastructure/new_issue >>>> >>>

3 6

Re: Inconsistent Ldap connection issues
by Gary Waters 16 Oct '24

16 Oct '24

> Are there any routers, middlewares, firewalls, idp's etc between the > client/ldap server? Load balancer? When this first started happening, the client a cluster of containers just spoke to ldap server directly over a peering connection. Since the error was unable to connect to ldap, I thought perhaps the one ldap server could not handle it. So I added a load balancer (AWS NLB) and a second ldap server. It didnt help. Since this was happening before the load balancer, I dont think its that. There is a ALB in front of the cluster. -Gary On 10/16/24 09:24, Gary Waters wrote: > >> >> Are there any routers, middlewares, firewalls, idp's etc between the >> client/ldap server? Load balancer? > > When this first started happening, the client a cluster of containers > just spoke to ldap server directly over a peering connection. Since > the error was unable to connect to ldap, I thought perhaps the one > ldap server could not handle it. So I added a load balancer (AWS NLB) > and a second ldap server. It didnt help. Since this was happening > before the load balancer, I dont think its that. There is a ALB in > front of the cluster. > > -Gary > > On 10/15/24 17:26, William Brown wrote: >>> >>>> These errors are only shown on the client, yes? Is there any >>>> evidence of a failed connection in the access log? >>> Correct, those 2 different contacting ldap error issues. I have >>> searched for various things in the logs, but I havent read it line >>> by line. I dont see "err=1", no fd errors, or "Not listening for new >>> connections - too many fds open". >> >> So, that means the error is happening *before* 389-ds gets a chance >> to accept on the connection. >> >>>> We encountered a similar issue recently with another load test, >>>> where the load tester wasn't averaging it's connections, it would >>>> launch 10,000 connections at once and hope they all worked. With >>>> your load test, is it actually spreading it's connections out, or >>>> is it bursting? >>> It's a ramp up of 500 users logging in and starting their searches, >>> the initial ramp up is 60 seconds, but the searches and >>> login/logouts is over 6 minutes. I just spliced up the logs to see >>> what that first minute was like: >>> >>> Peak Concurrent Connections: 689 >>> Total Operations: 18770 >>> Total Results: 18769 >>> Overall Performance: 100.0% >>> >>> Total Connections: 2603 (21.66/sec) (1299.40/min) >>> - LDAP Connections: 2603 (21.66/sec) (1299.40/min) >>> - LDAPI Connections: 0 (0.00/sec) (0.00/min) >>> - LDAPS Connections: 0 (0.00/sec) (0.00/min) >>> - StartTLS Extended Ops: 2571 (21.39/sec) (1283.42/min) >>> >>> Searches: 13596 (113.12/sec) (6787.01/min) >>> Modifications: 0 (0.00/sec) (0.00/min) >>> Adds: 0 (0.00/sec) (0.00/min) >>> Deletes: 0 (0.00/sec) (0.00/min) >>> Mod RDNs: 0 (0.00/sec) (0.00/min) >>> Compares: 0 (0.00/sec) (0.00/min) >>> Binds: 2603 (21.66/sec) (1299.40/min) >>> >>> With these settings below, the test results are in, they still get 1 >>> ldap error per test. >>> >>> net.ipv4.tcp_max_syn_backlog = 8192 >>> >>> net.core.somaxconn = 8192 >>> >>> Suggestions ? Should I bump these up more ? >>> >> We still don't know what the cause *is* so just tweaking values won't >> help. We need to know what layer is triggering the error before we >> make changes. >> >> Reading these numbers, this doesn't look like the server should be >> under any stress at all - I have tested with 2cpu / 4gb ram and can >> easily get 10,000 simultaneous connections launched and accepted by >> 389-ds. >> >> My thinking at this point is there is something in between the client >> and 389 that is not coping. >> >> >> >> -- >> Sincerely, >> >> William Brown >> >> Senior Software Engineer, >> Identity and Access Management >> SUSE Labs, Australia >>

1 0

Re: Inconsistent Ldap connection issues
by James Chapman 14 Oct '24

14 Oct '24

On Wed, Oct 9, 2024 at 11:36 AM Joe Fletcher <jfletche(a)sscinc.com> wrote: > Just a thought: what are the open files limits set to on the system? > > > > I’ve seen plenty of cases where increasing descriptor limits can help in > these instances. > > > > > > > > *From:* Thierry Bordaz via 389-users <389-users(a)lists.fedoraproject.org> > *Sent:* Wednesday, October 9, 2024 10:30 AM > *To:* Gary Waters <gwaters(a)caltech.edu>; General discussion list for the > 389 Directory server project. <389-users(a)lists.fedoraproject.org>; Marc > Sauton <msauton(a)redhat.com>; James Chapman <jachapma(a)redhat.com> > *Cc:* gwaters-web(a)caltech.edu; Thierry Bordaz <tbordaz(a)redhat.com> > *Subject:* [389-users] Re: Inconsistent Ldap connection issues > > > > **** The e-mail below is from an external source. Please do not open > attachments or click links from an unknown or suspicious origin. **** > > > > Hi Gary, > > My understanding is that a single client opens ~10K connections in ~6min, > that is an average of 26 connections per second. It creates a set of > established connections that spike up to 961 parallel connections. The > problem being that from time to time the client reports 'can not contact > LDAP server' and while you are running 2.4 this problem did not occur in > 1.4.3. Am I correct ? > > My first guess is that Marc is correct and tuning of tcp param should be > the culprit. Now it does not explain why it occurs only in 2.4 but may be > you were running 1.4.3 on RHEL7 and are running 2.4 on RHEL8. > > 2.4 contains significant changes around that area. I do not recall all > commit in connection handling side. AFAIK what is "new" is a dedicated > listener thread (polling on ports 389/636/ldapi for new connections) and a > multiple polling threads (polling the established connections) > My understanding is that your problem impacts the listener thread as it is > responsible to accept new connections and it is the new problem you detect > in 2.4. @james did I miss something ? > JC: There has been a lot of work around connection management around this version, the "accept" thread that is responsible for polling the ldap/ldaps ports for connection attempts was introduced in a previous version. This thread will fail to accept a new connection when the number of existing connections hits a certain limit. However, when this happens you should see this message in the error logs: "Not listening for new connections - too many fds open", so IMHO I think the error message you see is related to something else. > If the culprit is not in TCP tuning, @james do you remember known bugs > that would limit the listener thread ? > JC: I failed to reproduce this issue locally with the same version and file descriptor limit (8192) and 10k connections. So I am not aware of anything else that might cause this error message. > best regards > thierry > > On 10/8/24 7:36 PM, Gary Waters wrote: > > Hi Thierry, > > Ah yes of course. Here is 1 run of their web app load test, it is 6 > minutes long, and it should mostly be only the test it self. I will start > looking for > > We encountered 2 "Can not contact ldap server" errors during this run. > > 2 cant contact ldap server errors in this run > > ----------- Access Log Output ------------ > > Start of Logs: 08/Oct/2024:09:53:35.810833927 > End of Logs: 08/Oct/2024:09:59:52.361830449 > > Processed Log Time: 0 Hours, 6 Minutes, 16.550998016 Seconds > > Restarts: 1 > Secure Protocol Versions: > - TLS1.2 128-bit AES-GCM (9833 connections) > > Peak Concurrent Connections: 689 > Total Operations: 86412 > Total Results: 86412 > Overall Performance: 100.0% > > Total Connections: 9933 (26.38/sec) (1582.73/min) > - LDAP Connections: 9933 (26.38/sec) (1582.73/min) > - LDAPI Connections: 0 (0.00/sec) (0.00/min) > - LDAPS Connections: 0 (0.00/sec) (0.00/min) > - StartTLS Extended Ops: 9833 (26.11/sec) (1566.80/min) > > Searches: 66647 (176.99/sec) (10619.60/min) > Modifications: 0 (0.00/sec) (0.00/min) > Adds: 0 (0.00/sec) (0.00/min) > Deletes: 0 (0.00/sec) (0.00/min) > Mod RDNs: 0 (0.00/sec) (0.00/min) > Compares: 0 (0.00/sec) (0.00/min) > Binds: 9932 (26.38/sec) (1582.57/min) > > Average wtime (wait time): 0.001407368 > Average optime (op time): 0.003186859 > Average etime (elapsed time): 0.004591048 > > Multi-factor Authentications: 0 > Proxied Auth Operations: 0 > Persistent Searches: 0 > Internal Operations: 0 > Entry Operations: 0 > Extended Operations: 9833 > Abandoned Requests: 0 > Smart Referrals Received: 0 > > VLV Operations: 0 > VLV Unindexed Searches: 0 > VLV Unindexed Components: 0 > SORT Operations: 0 > > Entire Search Base Queries: 0 > Paged Searches: 0 > Unindexed Searches: 0 > Unindexed Components: 0 > Invalid Attribute Filters: 0 > FDs Taken: 9933 > FDs Returned: 9932 > Highest FD Taken: 961 > > Broken Pipes: 0 > Connections Reset By Peer: 0 > Resource Unavailable: 0 > Max BER Size Exceeded: 0 > > Binds: 9932 > Unbinds: 9225 > ----------------------------------- > - LDAP v2 Binds: 0 > - LDAP v3 Binds: 9932 > - AUTOBINDs(LDAPI): 0 > - SSL Client Binds: 0 > - Failed SSL Client Binds: 0 > - SASL Binds: 0 > - Directory Manager Binds: 0 > - Anonymous Binds: 99 > > ================ > > After this run I bumped up these from 4096, > > net.ipv4.tcp_max_syn_backlog = 6144 > net.core.somaxconn = 6144 > > Yet we still get the ldap errors (this one and the start tls request error > previously mentioned.) > > Should I bump up the > > On 10/8/24 03:47, Thierry Bordaz wrote: > > Hi Gary, > > I meant that the access logs covered 5hours. It would be helpful to > capture/focus on the logs from the few minutes before/after the time when > the problem occurred. Then check from those limited logs if there is a > pattern or unexpected events (long operation, no operation, abandon, ...) > > best regards > thierry > > On 10/7/24 7:37 PM, Gary Waters wrote: > > Hi Thierry, > > Ok I ll decrease the timeout to 15 seconds then. > > Reducing the size of the logs will help. > > Which log and how do I do this ? > > Thanks Marc and Theirry! > > -Gary > > On 10/7/24 00:26, Thierry Bordaz wrote: > > Hi, > > Those slap_poll error means that the server was unable to send back PDU to > the client. It can occur if the client sends a request and does not read > fast enough the results. The timeout is high 30s (30000), could it be that > the problem is on the client side (app) ? > > I suggest that you focus on the timestamp when the application reports a > failure. Then look in the access/error logs from 1-3min before and after > the time of the failure. Logconv from that limited scope will be more > helpful than a global one. > > The pattern looks to be an app opens a connection, switch to secure > connection (start-tls), issue 6-8 SRCH then close. etime/wtime/optime looks > fine but as it is an average (over 1M op) it is not helpful. Reducing the > size of the logs will help. > I found interesting the abandon op as it is possibly related to a > performance issue. > > best regards > thierry > > > > On 10/4/24 11:54 PM, Gary Waters via 389-users wrote: > > Hi Marc, > > I have made nsslapd-listen-backlog-size to 512. > > For the ioblocktimeout, I increased it because of an error I was seeing: > > [30/Sep/2024:16:26:55.987681019 -0700] - ERR - slapd_poll - (743) - Timed > out > [30/Sep/2024:16:34:49.646922635 -0700] - ERR - slapd_poll - (568) - Timed > out > > Googling stated that I should increase the ioblocktimeout. So I bumped it > up from 20000 to 30000. > > Since then, those slapd_poll timed out errors have not occurred. Should I > have changed something else? > > What should I increase these to? > > net.core.somaxconn = 4096 > net.ipv4.tcp_max_syn_backlog = 4096 > > Thanks so much for your help! > > -Gary > > On 10/4/24 11:55, Marc Sauton wrote: > > tune up nsslapd-listen-backlog-size > > and verify the net.core.somaxconn and net.ipv4.tcp_max_syn_backlog are > high enough ( sysctl -a ) > > possibly tune down the nsslapd-ioblocktimeout value > > Thanks, > > M. > > > > On Fri, Oct 4, 2024 at 11:06 AM gwaters-web--- via 389-users < > 389-users(a)lists.fedoraproject.org> wrote: > > Hello, > > We are experiencing a new issue since we upgraded from 389-ds-base from > 1.4~ish to 2.0.15 on RHEL 8. I couldnt figure how to fix it, so I > switched to RHEL9 and are on 2.4.5-9. > > The issue is during a performance load test of a web application. The > app logs into a website and does some things that searches against ldap, > and does some transactions. This app has been performing fine for years, > the app has changed so it could be something there, but I am not sure > about that because of the percentage of the traffic that is successful. > > The errors for the web app are "Can't contact Ldap Server" and sometimes > "Can't contact LDAP server. Start TLS request accepted.Server willing to > negotiate SSL. (0xFFFF [-1])". Out of the 128k connections below, these > errors will happen like 5 or 6 times, so its wildly inconsistent and > random. > > I did a logconv analysis with 6 hours of a day of testing, see below. > One thing that really stood out to me was the peak concurrent > connections = 22.. That peak is so low, I dont know how these errors are > happening. > > I dont see any errors in the access log ( grepping for err=1). > I looked for cache warnings/errors in the access/errors logs, but didnt > find any. I dont see things like unavailable connections in the access > logs. > > Suggestions on what to change or look for in the logs ? > > Thanks, > Gary > > > information: > Machine Size: 16G of ram, 4 core AMD (its an EC2.m5.large, gp3 disk type) > > kernel: > Linux 5.14.0-427.35.1.el9_4.x86_64 #1 SMP PREEMPT_DYNAMIC > packages: > 389-ds-base-libs-2.4.5-9.el9_4.x86_64 > 389-ds-base-2.4.5-9.el9_4.x86_64 > > single instance of dirsrv running > dirsrv modifcations from default: > > nsslapd-logging-backend: dirsrv-log,syslog > nsslapd-maxdescriptors: 8192 > nsslapd-listen-backlog-size: 256 > nsslapd-allow-hashed-passwords: on > nsslapd-idletimeout: 30 > nsslapd-ioblocktimeout: 30000 > nsslapd-sizelimit: -1 > nsslapd-auditlog-logging-enabled: off > nsslapd-lookthroughlimit: -1 > > dirsrv.systemd: > limitNOFILE=8192 > > >Total Log Lines Analszed: 2694287 > > > > > > > > ---------- Access Log Output ------------ > > > > Start of Logs: 26/Sep/2024:10:07:32.089983378 > > End of Logs: 26/Sep/2024:15:54:29.895403688 > > > > Processed Log Time: 5 Hours, 46 Minutes, 57.805426688 Seconds > > > > Restarts: 0 > > Secure Protocol Versions: > > - TLS1.2 128-bit AES-GCM (123117 connections) > > > > Peak Concurrent Connections: 22 > > Total Operations: 1097043 > > Total Results: 1097044 > > Overall Performance: 100.0% > > > > Total Connections: 128646 (6.18/sec) (370.78/min) > > - LDAP Connections: 128646 (6.18/sec) (370.78/min) > > - LDAPI Connections: 0 (0.00/sec) (0.00/min) > > - LDAPS Connections: 0 (0.00/sec) (0.00/min) > > - StartTLS Extended Ops: 123116 (5.91/sec) (354.84/min) > > > > Searches: 845279 (40.60/sec) (2436.22/min) > > Modifications: 0 (0.00/sec) (0.00/min) > > Adds: 0 (0.00/sec) (0.00/min) > > Deletes: 0 (0.00/sec) (0.00/min) > > Mod RDNs: 0 (0.00/sec) (0.00/min) > > Compares: 0 (0.00/sec) (0.00/min) > > Binds: 128647 (6.18/sec) (370.78/min) > > > > Average wtime (wait time): 0.001560856 > > Average optime (op time): 0.003310453 > > Average etime (elapsed time): 0.004868040 > > > > Multi-factor Authentications: 0 > > Proxied Auth Operations: 0 > > Persistent Searches: 0 > > Internal Operations: 0 > > Entry Operations: 0 > > Extended Operations: 123116 > > Abandoned Requests: 1 > > Smart Referrals Received: 0 > > > > VLV Operations: 0 > > VLV Unindexed Searches: 0 > > VLV Unindexed Components: 0 > > SORT Operations: 0 > > > > Entire Search Base Queries: 0 > > Paged Searches: 0 > > Unindexed Searches: 0 > > Unindexed Components: 0 > > Invalid Attribute Filters: 0 > > FDs Taken: 128646 > > FDs Returned: 129318 > > Highest FD Taken: 968 > > > > Broken Pipes: 0 > > Connections Reset By Peer: 0 > > Resource Unavailable: 0 > > Max BER Size Exceeded: 0 > > > > Binds: 128647 > > Unbinds: 119206 > > ------------------------------------- > > - LDAP v2 Binds: 0 > > - LDAP v3 Binds: 128647 > > - AUTOBINDs(LDAPI): 0 > > - SSL Client Binds: 0 > > - Failed SSL Client Binds: 0 > > - SASL Binds: 0 > > - Dir > > -- > _______________________________________________ > 389-users mailing list -- 389-users(a)lists.fedoraproject.org > To unsubscribe send an email to 389-users-leave(a)lists.fedoraproject.org > Fedora Code of Conduct: > https://docs.fedoraproject.org/en-US/project/code-of-conduct/ > <https://urldefense.com/v3/__https:/docs.fedoraproject.org/en-US/project/cod…> > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines > <https://urldefense.com/v3/__https:/fedoraproject.org/wiki/Mailing_list_guid…> > List Archives: > https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject… > <https://urldefense.com/v3/__https:/lists.fedoraproject.org/archives/list/38…> > Do not reply to spam, report it: > https://pagure.io/fedora-infrastructure/new_issue > <https://urldefense.com/v3/__https:/pagure.io/fedora-infrastructure/new_issu…> > > > >

2 1

Re: Inconsistent Ldap connection issues
by Gary Waters 14 Oct '24

14 Oct '24

cat /proc/sys/fs/file-max 9223372036854775807 The file descriptor limit of dirsrv is 8192. Should I bump this up too? I just used what was on the 389 website. Thanks, Gary On 10/9/24 03:06, Joe Fletcher wrote: > > Just a thought: what are the open files limits set to on the system? > > I’ve seen plenty of cases where increasing descriptor limits can help > in these instances. > > *From:*Thierry Bordaz via 389-users <389-users(a)lists.fedoraproject.org> > *Sent:* Wednesday, October 9, 2024 10:30 AM > *To:* Gary Waters <gwaters(a)caltech.edu>; General discussion list for > the 389 Directory server project. <389-users(a)lists.fedoraproject.org>; > Marc Sauton <msauton(a)redhat.com>; James Chapman <jachapma(a)redhat.com> > *Cc:* gwaters-web(a)caltech.edu; Thierry Bordaz <tbordaz(a)redhat.com> > *Subject:* [389-users] Re: Inconsistent Ldap connection issues > > **** The e-mail below is from an external source. Please do not open > attachments or click links from an unknown or suspicious origin. **** > > Hi Gary, > > My understanding is that a single client opens ~10K connections in > ~6min, that is an average of 26 connections per second. It creates a > set of established connections that spike up to 961 parallel > connections. The problem being that from time to time the client > reports 'can not contact LDAP server' and while you are running 2.4 > this problem did not occur in 1.4.3. Am I correct ? > > My first guess is that Marc is correct and tuning of tcp param should > be the culprit. Now it does not explain why it occurs only in 2.4 but > may be you were running 1.4.3 on RHEL7 and are running 2.4 on RHEL8. > > 2.4 contains significant changes around that area. I do not recall all > commit in connection handling side. AFAIK what is "new" is a dedicated > listener thread (polling on ports 389/636/ldapi for new connections) > and a multiple polling threads (polling the established connections) > My understanding is that your problem impacts the listener thread as > it is responsible to accept new connections and it is the new problem > you detect in 2.4. @james did I miss something ? > > If the culprit is not in TCP tuning, @james do you remember known bugs > that would limit the listener thread ? > > best regards > thierry > > On 10/8/24 7:36 PM, Gary Waters wrote: > > Hi Thierry, > > Ah yes of course. Here is 1 run of their web app load test, it is > 6 minutes long, and it should mostly be only the test it self. I > will start looking for > > We encountered 2 "Can not contact ldap server" errors during this > run. > > 2 cant contact ldap server errors in this run > > ----------- Access Log Output ------------ > > Start of Logs: 08/Oct/2024:09:53:35.810833927 > End of Logs: 08/Oct/2024:09:59:52.361830449 > > Processed Log Time: 0 Hours, 6 Minutes, 16.550998016 Seconds > > Restarts: 1 > Secure Protocol Versions: > - TLS1.2 128-bit AES-GCM (9833 connections) > > Peak Concurrent Connections: 689 > Total Operations: 86412 > Total Results: 86412 > Overall Performance: 100.0% > > Total Connections: 9933 (26.38/sec) (1582.73/min) > - LDAP Connections: 9933 (26.38/sec) (1582.73/min) > - LDAPI Connections: 0 (0.00/sec) (0.00/min) > - LDAPS Connections: 0 (0.00/sec) (0.00/min) > - StartTLS Extended Ops: 9833 (26.11/sec) (1566.80/min) > > Searches: 66647 (176.99/sec) > (10619.60/min) > Modifications: 0 (0.00/sec) (0.00/min) > Adds: 0 (0.00/sec) (0.00/min) > Deletes: 0 (0.00/sec) (0.00/min) > Mod RDNs: 0 (0.00/sec) (0.00/min) > Compares: 0 (0.00/sec) (0.00/min) > Binds: 9932 (26.38/sec) (1582.57/min) > > Average wtime (wait time): 0.001407368 > Average optime (op time): 0.003186859 > Average etime (elapsed time): 0.004591048 > > Multi-factor Authentications: 0 > Proxied Auth Operations: 0 > Persistent Searches: 0 > Internal Operations: 0 > Entry Operations: 0 > Extended Operations: 9833 > Abandoned Requests: 0 > Smart Referrals Received: 0 > > VLV Operations: 0 > VLV Unindexed Searches: 0 > VLV Unindexed Components: 0 > SORT Operations: 0 > > Entire Search Base Queries: 0 > Paged Searches: 0 > Unindexed Searches: 0 > Unindexed Components: 0 > Invalid Attribute Filters: 0 > FDs Taken: 9933 > FDs Returned: 9932 > Highest FD Taken: 961 > > Broken Pipes: 0 > Connections Reset By Peer: 0 > Resource Unavailable: 0 > Max BER Size Exceeded: 0 > > Binds: 9932 > Unbinds: 9225 > ----------------------------------- > - LDAP v2 Binds: 0 > - LDAP v3 Binds: 9932 > - AUTOBINDs(LDAPI): 0 > - SSL Client Binds: 0 > - Failed SSL Client Binds: 0 > - SASL Binds: 0 > - Directory Manager Binds: 0 > - Anonymous Binds: 99 > > ================ > > After this run I bumped up these from 4096, > > net.ipv4.tcp_max_syn_backlog = 6144 > net.core.somaxconn = 6144 > > Yet we still get the ldap errors (this one and the start tls > request error previously mentioned.) > > Should I bump up the > > On 10/8/24 03:47, Thierry Bordaz wrote: > > Hi Gary, > > I meant that the access logs covered 5hours. It would be > helpful to capture/focus on the logs from the few minutes > before/after the time when the problem occurred. Then check > from those limited logs if there is a pattern or unexpected > events (long operation, no operation, abandon, ...) > > best regards > thierry > > On 10/7/24 7:37 PM, Gary Waters wrote: > > Hi Thierry, > > Ok I ll decrease the timeout to 15 seconds then. > > Reducing the size of the logs will help. > > Which log and how do I do this ? > > Thanks Marc and Theirry! > > -Gary > > On 10/7/24 00:26, Thierry Bordaz wrote: > > Hi, > > Those slap_poll error means that the server was unable > to send back PDU to the client. It can occur if the > client sends a request and does not read fast enough > the results. The timeout is high 30s (30000), could it > be that the problem is on the client side (app) ? > > I suggest that you focus on the timestamp when the > application reports a failure. Then look in the > access/error logs from 1-3min before and after the > time of the failure. Logconv from that limited scope > will be more helpful than a global one. > > The pattern looks to be an app opens a connection, > switch to secure connection (start-tls), issue 6-8 > SRCH then close. etime/wtime/optime looks fine but as > it is an average (over 1M op) it is not helpful. > Reducing the size of the logs will help. > I found interesting the abandon op as it is possibly > related to a performance issue. > > best regards > thierry > > On 10/4/24 11:54 PM, Gary Waters via 389-users wrote: > > Hi Marc, > > I have made nsslapd-listen-backlog-size to 512. > > For the ioblocktimeout, I increased it because of > an error I was seeing: > > [30/Sep/2024:16:26:55.987681019 -0700] - ERR - > slapd_poll - (743) - Timed out > [30/Sep/2024:16:34:49.646922635 -0700] - ERR - > slapd_poll - (568) - Timed out > > Googling stated that I should increase the > ioblocktimeout. So I bumped it up from 20000 to 30000. > > Since then, those slapd_poll timed out errors have > not occurred. Should I have changed something else? > > What should I increase these to? > > net.core.somaxconn = 4096 > net.ipv4.tcp_max_syn_backlog = 4096 > > Thanks so much for your help! > > -Gary > > On 10/4/24 11:55, Marc Sauton wrote: > > tune up nsslapd-listen-backlog-size > > and verify the net.core.somaxconn > and net.ipv4.tcp_max_syn_backlog are high > enough ( sysctl -a ) > > possibly tune down the nsslapd-ioblocktimeout > value > > Thanks, > > M. > > On Fri, Oct 4, 2024 at 11:06 AM gwaters-web--- > via 389-users > <389-users(a)lists.fedoraproject.org> wrote: > > Hello, > > We are experiencing a new issue since we > upgraded from 389-ds-base from > 1.4~ish to 2.0.15 on RHEL 8. I couldnt > figure how to fix it, so I > switched to RHEL9 and are on 2.4.5-9. > > The issue is during a performance load > test of a web application. The > app logs into a website and does some > things that searches against ldap, > and does some transactions. This app has > been performing fine for years, > the app has changed so it could be > something there, but I am not sure > about that because of the percentage of > the traffic that is successful. > > The errors for the web app are "Can't > contact Ldap Server" and sometimes > "Can't contact LDAP server. Start TLS > request accepted.Server willing to > negotiate SSL. (0xFFFF [-1])". Out of the > 128k connections below, these > errors will happen like 5 or 6 times, so > its wildly inconsistent and random. > > I did a logconv analysis with 6 hours of a > day of testing, see below. > One thing that really stood out to me was > the peak concurrent > connections = 22.. That peak is so low, I > dont know how these errors are > happening. > > I dont see any errors in the access log ( > grepping for err=1). > I looked for cache warnings/errors in the > access/errors logs, but didnt > find any. I dont see things like > unavailable connections in the access logs. > > Suggestions on what to change or look for > in the logs ? > > Thanks, > Gary > > > information: > Machine Size: 16G of ram, 4 core AMD (its > an EC2.m5.large, gp3 disk type) > > kernel: > Linux 5.14.0-427.35.1.el9_4.x86_64 #1 SMP > PREEMPT_DYNAMIC > packages: > 389-ds-base-libs-2.4.5-9.el9_4.x86_64 > 389-ds-base-2.4.5-9.el9_4.x86_64 > > single instance of dirsrv running > dirsrv modifcations from default: > > nsslapd-logging-backend: dirsrv-log,syslog > nsslapd-maxdescriptors: 8192 > nsslapd-listen-backlog-size: 256 > nsslapd-allow-hashed-passwords: on > nsslapd-idletimeout: 30 > nsslapd-ioblocktimeout: 30000 > nsslapd-sizelimit: -1 > nsslapd-auditlog-logging-enabled: off > nsslapd-lookthroughlimit: -1 > > dirsrv.systemd: > limitNOFILE=8192 > > >Total Log Lines Analszed: 2694287 > > > > > > > > ---------- Access Log Output ------------ > > > > Start of Logs: > 26/Sep/2024:10:07:32.089983378 > > End of Logs: 26/Sep/2024:15:54:29.895403688 > > > > Processed Log Time: 5 Hours, 46 > Minutes, 57.805426688 Seconds > > > > Restarts: 0 > > Secure Protocol Versions: > > - TLS1.2 128-bit AES-GCM (123117 > connections) > > > > Peak Concurrent Connections: 22 > > Total Operations: 1097043 > > Total Results: 1097044 > > Overall Performance: 100.0% > > > > Total Connections: 128646 > (6.18/sec) (370.78/min) > > - LDAP Connections: 128646 > (6.18/sec) (370.78/min) > > - LDAPI Connections: 0 > (0.00/sec) (0.00/min) > > - LDAPS Connections: 0 > (0.00/sec) (0.00/min) > > - StartTLS Extended Ops: 123116 > (5.91/sec) (354.84/min) > > > > Searches: 845279 (40.60/sec) > (2436.22/min) > > Modifications: 0 (0.00/sec) > (0.00/min) > > Adds: 0 (0.00/sec) (0.00/min) > > Deletes: 0 (0.00/sec) > (0.00/min) > > Mod RDNs: 0 (0.00/sec) > (0.00/min) > > Compares: 0 (0.00/sec) > (0.00/min) > > Binds: 128647 (6.18/sec) > (370.78/min) > > > > Average wtime (wait time): 0.001560856 > > Average optime (op time): 0.003310453 > > Average etime (elapsed time): 0.004868040 > > > > Multi-factor Authentications: 0 > > Proxied Auth Operations: 0 > > Persistent Searches: 0 > > Internal Operations: 0 > > Entry Operations: 0 > > Extended Operations: 123116 > > Abandoned Requests: 1 > > Smart Referrals Received: 0 > > > > VLV Operations: 0 > > VLV Unindexed Searches: 0 > > VLV Unindexed Components: 0 > > SORT Operations: 0 > > > > Entire Search Base Queries: 0 > > Paged Searches: 0 > > Unindexed Searches: 0 > > Unindexed Components: 0 > > Invalid Attribute Filters: 0 > > FDs Taken: 128646 > > FDs Returned: 129318 > > Highest FD Taken: 968 > > > > Broken Pipes: 0 > > Connections Reset By Peer: 0 > > Resource Unavailable: 0 > > Max BER Size Exceeded: 0 > > > > Binds: 128647 > > Unbinds: 119206 > > ------------------------------------- > > - LDAP v2 Binds: 0 > > - LDAP v3 Binds: 128647 > > - AUTOBINDs(LDAPI): 0 > > - SSL Client Binds: 0 > > - Failed SSL Client Binds: 0 > > - SASL Binds: 0 > > - Dir > > -- > _______________________________________________ > 389-users mailing list -- > 389-users(a)lists.fedoraproject.org > To unsubscribe send an email to > 389-users-leave(a)lists.fedoraproject.org > Fedora Code of Conduct: > https://docs.fedoraproject.org/en-US/project/code-of-conduct/ > <https://urldefense.com/v3/__https:/docs.fedoraproject.org/en-US/project/cod…> > List Guidelines: > https://fedoraproject.org/wiki/Mailing_list_guidelines > <https://urldefense.com/v3/__https:/fedoraproject.org/wiki/Mailing_list_guid…> > List Archives: > https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject… > <https://urldefense.com/v3/__https:/lists.fedoraproject.org/archives/list/38…> > Do not reply to spam, report it: > https://pagure.io/fedora-infrastructure/new_issue > <https://urldefense.com/v3/__https:/pagure.io/fedora-infrastructure/new_issu…> > > >

1 0

Re: Inconsistent Ldap connection issues
by Thierry Bordaz 14 Oct '24

14 Oct '24

Hi Gary, My understanding is that a single client opens ~10K connections in ~6min, that is an average of 26 connections per second. It creates a set of established connections that spike up to 961 parallel connections. The problem being that from time to time the client reports 'can not contact LDAP server' and while you are running 2.4 this problem did not occur in 1.4.3. Am I correct ? My first guess is that Marc is correct and tuning of tcp param should be the culprit. Now it does not explain why it occurs only in 2.4 but may be you were running 1.4.3 on RHEL7 and are running 2.4 on RHEL8. 2.4 contains significant changes around that area. I do not recall all commit in connection handling side. AFAIK what is "new" is a dedicated listener thread (polling on ports 389/636/ldapi for new connections) and a multiple polling threads (polling the established connections) My understanding is that your problem impacts the listener thread as it is responsible to accept new connections and it is the new problem you detect in 2.4. @james did I miss something ? If the culprit is not in TCP tuning, @james do you remember known bugs that would limit the listener thread ? best regards thierry On 10/8/24 7:36 PM, Gary Waters wrote: > > Hi Thierry, > > Ah yes of course. Here is 1 run of their web app load test, it is 6 > minutes long, and it should mostly be only the test it self. I will > start looking for > > We encountered 2 "Can not contact ldap server" errors during this run. > > 2 cant contact ldap server errors in this run > > ----------- Access Log Output ------------ > > Start of Logs: 08/Oct/2024:09:53:35.810833927 > End of Logs: 08/Oct/2024:09:59:52.361830449 > > Processed Log Time: 0 Hours, 6 Minutes, 16.550998016 Seconds > > Restarts: 1 > Secure Protocol Versions: > - TLS1.2 128-bit AES-GCM (9833 connections) > > Peak Concurrent Connections: 689 > Total Operations: 86412 > Total Results: 86412 > Overall Performance: 100.0% > > Total Connections: 9933 (26.38/sec) (1582.73/min) > - LDAP Connections: 9933 (26.38/sec) (1582.73/min) > - LDAPI Connections: 0 (0.00/sec) (0.00/min) > - LDAPS Connections: 0 (0.00/sec) (0.00/min) > - StartTLS Extended Ops: 9833 (26.11/sec) (1566.80/min) > > Searches: 66647 (176.99/sec) (10619.60/min) > Modifications: 0 (0.00/sec) (0.00/min) > Adds: 0 (0.00/sec) (0.00/min) > Deletes: 0 (0.00/sec) (0.00/min) > Mod RDNs: 0 (0.00/sec) (0.00/min) > Compares: 0 (0.00/sec) (0.00/min) > Binds: 9932 (26.38/sec) (1582.57/min) > > Average wtime (wait time): 0.001407368 > Average optime (op time): 0.003186859 > Average etime (elapsed time): 0.004591048 > > Multi-factor Authentications: 0 > Proxied Auth Operations: 0 > Persistent Searches: 0 > Internal Operations: 0 > Entry Operations: 0 > Extended Operations: 9833 > Abandoned Requests: 0 > Smart Referrals Received: 0 > > VLV Operations: 0 > VLV Unindexed Searches: 0 > VLV Unindexed Components: 0 > SORT Operations: 0 > > Entire Search Base Queries: 0 > Paged Searches: 0 > Unindexed Searches: 0 > Unindexed Components: 0 > Invalid Attribute Filters: 0 > FDs Taken: 9933 > FDs Returned: 9932 > Highest FD Taken: 961 > > Broken Pipes: 0 > Connections Reset By Peer: 0 > Resource Unavailable: 0 > Max BER Size Exceeded: 0 > > Binds: 9932 > Unbinds: 9225 > ----------------------------------- > - LDAP v2 Binds: 0 > - LDAP v3 Binds: 9932 > - AUTOBINDs(LDAPI): 0 > - SSL Client Binds: 0 > - Failed SSL Client Binds: 0 > - SASL Binds: 0 > - Directory Manager Binds: 0 > - Anonymous Binds: 99 > > ================ > > After this run I bumped up these from 4096, > > net.ipv4.tcp_max_syn_backlog = 6144 > net.core.somaxconn = 6144 > > Yet we still get the ldap errors (this one and the start tls request > error previously mentioned.) > > Should I bump up the > > On 10/8/24 03:47, Thierry Bordaz wrote: >> >> Hi Gary, >> >> I meant that the access logs covered 5hours. It would be helpful to >> capture/focus on the logs from the few minutes before/after the time >> when the problem occurred. Then check from those limited logs if >> there is a pattern or unexpected events (long operation, no >> operation, abandon, ...) >> >> best regards >> thierry >> >> On 10/7/24 7:37 PM, Gary Waters wrote: >>> >>> Hi Thierry, >>> >>> Ok I ll decrease the timeout to 15 seconds then. >>> >>>> Reducing the size of the logs will help. >>> Which log and how do I do this ? >>> >>> Thanks Marc and Theirry! >>> >>> -Gary >>> >>> On 10/7/24 00:26, Thierry Bordaz wrote: >>>> >>>> Hi, >>>> >>>> Those slap_poll error means that the server was unable to send back >>>> PDU to the client. It can occur if the client sends a request and >>>> does not read fast enough the results. The timeout is high 30s >>>> (30000), could it be that the problem is on the client side (app) ? >>>> >>>> I suggest that you focus on the timestamp when the application >>>> reports a failure. Then look in the access/error logs from 1-3min >>>> before and after the time of the failure. Logconv from that limited >>>> scope will be more helpful than a global one. >>>> >>>> The pattern looks to be an app opens a connection, switch to secure >>>> connection (start-tls), issue 6-8 SRCH then close. >>>> etime/wtime/optime looks fine but as it is an average (over 1M op) >>>> it is not helpful. Reducing the size of the logs will help. >>>> I found interesting the abandon op as it is possibly related to a >>>> performance issue. >>>> >>>> best regards >>>> thierry >>>> >>>> >>>> On 10/4/24 11:54 PM, Gary Waters via 389-users wrote: >>>>> >>>>> Hi Marc, >>>>> >>>>> I have made nsslapd-listen-backlog-size to 512. >>>>> >>>>> For the ioblocktimeout, I increased it because of an error I was >>>>> seeing: >>>>> >>>>> [30/Sep/2024:16:26:55.987681019 -0700] - ERR - slapd_poll - (743) >>>>> - Timed out >>>>> [30/Sep/2024:16:34:49.646922635 -0700] - ERR - slapd_poll - (568) >>>>> - Timed out >>>>> >>>>> Googling stated that I should increase the ioblocktimeout. So I >>>>> bumped it up from 20000 to 30000. >>>>> >>>>> Since then, those slapd_poll timed out errors have not occurred. >>>>> Should I have changed something else? >>>>> >>>>> What should I increase these to? >>>>> >>>>> net.core.somaxconn = 4096 >>>>> net.ipv4.tcp_max_syn_backlog = 4096 >>>>> >>>>> Thanks so much for your help! >>>>> >>>>> -Gary >>>>> >>>>> On 10/4/24 11:55, Marc Sauton wrote: >>>>>> tune up nsslapd-listen-backlog-size >>>>>> and verify the net.core.somaxconn >>>>>> and net.ipv4.tcp_max_syn_backlog are high enough ( sysctl -a ) >>>>>> possibly tune down the nsslapd-ioblocktimeout value >>>>>> Thanks, >>>>>> M. >>>>>> >>>>>> On Fri, Oct 4, 2024 at 11:06 AM gwaters-web--- via 389-users >>>>>> <389-users(a)lists.fedoraproject.org> wrote: >>>>>> >>>>>> Hello, >>>>>> >>>>>> We are experiencing a new issue since we upgraded from >>>>>> 389-ds-base from >>>>>> 1.4~ish to 2.0.15 on RHEL 8. I couldnt figure how to fix it, >>>>>> so I >>>>>> switched to RHEL9 and are on 2.4.5-9. >>>>>> >>>>>> The issue is during a performance load test of a web >>>>>> application. The >>>>>> app logs into a website and does some things that searches >>>>>> against ldap, >>>>>> and does some transactions. This app has been performing fine >>>>>> for years, >>>>>> the app has changed so it could be something there, but I am >>>>>> not sure >>>>>> about that because of the percentage of the traffic that is >>>>>> successful. >>>>>> >>>>>> The errors for the web app are "Can't contact Ldap Server" >>>>>> and sometimes >>>>>> "Can't contact LDAP server. Start TLS request accepted.Server >>>>>> willing to >>>>>> negotiate SSL. (0xFFFF [-1])". Out of the 128k connections >>>>>> below, these >>>>>> errors will happen like 5 or 6 times, so its wildly >>>>>> inconsistent and random. >>>>>> >>>>>> I did a logconv analysis with 6 hours of a day of testing, >>>>>> see below. >>>>>> One thing that really stood out to me was the peak concurrent >>>>>> connections = 22.. That peak is so low, I dont know how these >>>>>> errors are >>>>>> happening. >>>>>> >>>>>> I dont see any errors in the access log ( grepping for err=1). >>>>>> I looked for cache warnings/errors in the access/errors logs, >>>>>> but didnt >>>>>> find any. I dont see things like unavailable connections in >>>>>> the access logs. >>>>>> >>>>>> Suggestions on what to change or look for in the logs ? >>>>>> >>>>>> Thanks, >>>>>> Gary >>>>>> >>>>>> >>>>>> information: >>>>>> Machine Size: 16G of ram, 4 core AMD (its an EC2.m5.large, >>>>>> gp3 disk type) >>>>>> >>>>>> kernel: >>>>>> Linux 5.14.0-427.35.1.el9_4.x86_64 #1 SMP PREEMPT_DYNAMIC >>>>>> packages: >>>>>> 389-ds-base-libs-2.4.5-9.el9_4.x86_64 >>>>>> 389-ds-base-2.4.5-9.el9_4.x86_64 >>>>>> >>>>>> single instance of dirsrv running >>>>>> dirsrv modifcations from default: >>>>>> >>>>>> nsslapd-logging-backend: dirsrv-log,syslog >>>>>> nsslapd-maxdescriptors: 8192 >>>>>> nsslapd-listen-backlog-size: 256 >>>>>> nsslapd-allow-hashed-passwords: on >>>>>> nsslapd-idletimeout: 30 >>>>>> nsslapd-ioblocktimeout: 30000 >>>>>> nsslapd-sizelimit: -1 >>>>>> nsslapd-auditlog-logging-enabled: off >>>>>> nsslapd-lookthroughlimit: -1 >>>>>> >>>>>> dirsrv.systemd: >>>>>> limitNOFILE=8192 >>>>>> >>>>>> >Total Log Lines Analszed: 2694287 >>>>>> > >>>>>> > >>>>>> > >>>>>> > ---------- Access Log Output ------------ >>>>>> > >>>>>> > Start of Logs: 26/Sep/2024:10:07:32.089983378 >>>>>> > End of Logs: 26/Sep/2024:15:54:29.895403688 >>>>>> > >>>>>> > Processed Log Time: 5 Hours, 46 Minutes, 57.805426688 Seconds >>>>>> > >>>>>> > Restarts: 0 >>>>>> > Secure Protocol Versions: >>>>>> > - TLS1.2 128-bit AES-GCM (123117 connections) >>>>>> > >>>>>> > Peak Concurrent Connections: 22 >>>>>> > Total Operations: 1097043 >>>>>> > Total Results: 1097044 >>>>>> > Overall Performance: 100.0% >>>>>> > >>>>>> > Total Connections: 128646 (6.18/sec) (370.78/min) >>>>>> > - LDAP Connections: 128646 (6.18/sec) (370.78/min) >>>>>> > - LDAPI Connections: 0 (0.00/sec) (0.00/min) >>>>>> > - LDAPS Connections: 0 (0.00/sec) (0.00/min) >>>>>> > - StartTLS Extended Ops: 123116 (5.91/sec) (354.84/min) >>>>>> > >>>>>> > Searches: 845279 (40.60/sec) >>>>>> (2436.22/min) >>>>>> > Modifications: 0 (0.00/sec) (0.00/min) >>>>>> > Adds: 0 (0.00/sec) (0.00/min) >>>>>> > Deletes: 0 (0.00/sec) (0.00/min) >>>>>> > Mod RDNs: 0 (0.00/sec) (0.00/min) >>>>>> > Compares: 0 (0.00/sec) (0.00/min) >>>>>> > Binds: 128647 (6.18/sec) (370.78/min) >>>>>> > >>>>>> > Average wtime (wait time): 0.001560856 >>>>>> > Average optime (op time): 0.003310453 >>>>>> > Average etime (elapsed time): 0.004868040 >>>>>> > >>>>>> > Multi-factor Authentications: 0 >>>>>> > Proxied Auth Operations: 0 >>>>>> > Persistent Searches: 0 >>>>>> > Internal Operations: 0 >>>>>> > Entry Operations: 0 >>>>>> > Extended Operations: 123116 >>>>>> > Abandoned Requests: 1 >>>>>> > Smart Referrals Received: 0 >>>>>> > >>>>>> > VLV Operations: 0 >>>>>> > VLV Unindexed Searches: 0 >>>>>> > VLV Unindexed Components: 0 >>>>>> > SORT Operations: 0 >>>>>> > >>>>>> > Entire Search Base Queries: 0 >>>>>> > Paged Searches: 0 >>>>>> > Unindexed Searches: 0 >>>>>> > Unindexed Components: 0 >>>>>> > Invalid Attribute Filters: 0 >>>>>> > FDs Taken: 128646 >>>>>> > FDs Returned: 129318 >>>>>> > Highest FD Taken: 968 >>>>>> > >>>>>> > Broken Pipes: 0 >>>>>> > Connections Reset By Peer: 0 >>>>>> > Resource Unavailable: 0 >>>>>> > Max BER Size Exceeded: 0 >>>>>> > >>>>>> > Binds: 128647 >>>>>> > Unbinds: 119206 >>>>>> > ------------------------------------- >>>>>> > - LDAP v2 Binds: 0 >>>>>> > - LDAP v3 Binds: 128647 >>>>>> > - AUTOBINDs(LDAPI): 0 >>>>>> > - SSL Client Binds: 0 >>>>>> > - Failed SSL Client Binds: 0 >>>>>> > - SASL Binds: 0 >>>>>> > - Dir >>>>>> >>>>>> -- >>>>>> _______________________________________________ >>>>>> 389-users mailing list -- 389-users(a)lists.fedoraproject.org >>>>>> To unsubscribe send an email to >>>>>> 389-users-leave(a)lists.fedoraproject.org >>>>>> Fedora Code of Conduct: >>>>>> https://docs.fedoraproject.org/en-US/project/code-of-conduct/ >>>>>> List Guidelines: >>>>>> https://fedoraproject.org/wiki/Mailing_list_guidelines >>>>>> List Archives: >>>>>> https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject… >>>>>> Do not reply to spam, report it: >>>>>> https://pagure.io/fedora-infrastructure/new_issue >>>>>> >>>>>

2 1

Inconsistent Ldap connection issues
by gwaters-web＠caltech.edu 07 Oct '24

07 Oct '24

Hello, We are experiencing a new issue since we upgraded from 389-ds-base from 1.4~ish to 2.0.15 on RHEL 8. I couldnt figure how to fix it, so I switched to RHEL9 and are on 2.4.5-9. The issue is during a performance load test of a web application. The app logs into a website and does some things that searches against ldap, and does some transactions. This app has been performing fine for years, the app has changed so it could be something there, but I am not sure about that because of the percentage of the traffic that is successful. The errors for the web app are "Can't contact Ldap Server" and sometimes "Can't contact LDAP server. Start TLS request accepted.Server willing to negotiate SSL. (0xFFFF [-1])". Out of the 128k connections below, these errors will happen like 5 or 6 times, so its wildly inconsistent and random. I did a logconv analysis with 6 hours of a day of testing, see below. One thing that really stood out to me was the peak concurrent connections = 22.. That peak is so low, I dont know how these errors are happening. I dont see any errors in the access log ( grepping for err=1). I looked for cache warnings/errors in the access/errors logs, but didnt find any. I dont see things like unavailable connections in the access logs. Suggestions on what to change or look for in the logs ? Thanks, Gary information: Machine Size: 16G of ram, 4 core AMD (its an EC2.m5.large, gp3 disk type) kernel: Linux 5.14.0-427.35.1.el9_4.x86_64 #1 SMP PREEMPT_DYNAMIC packages: 389-ds-base-libs-2.4.5-9.el9_4.x86_64 389-ds-base-2.4.5-9.el9_4.x86_64 single instance of dirsrv running dirsrv modifcations from default: nsslapd-logging-backend: dirsrv-log,syslog nsslapd-maxdescriptors: 8192 nsslapd-listen-backlog-size: 256 nsslapd-allow-hashed-passwords: on nsslapd-idletimeout: 30 nsslapd-ioblocktimeout: 30000 nsslapd-sizelimit: -1 nsslapd-auditlog-logging-enabled: off nsslapd-lookthroughlimit: -1 dirsrv.systemd: limitNOFILE=8192 >Total Log Lines Analszed: 2694287 > > > > ---------- Access Log Output ------------ > > Start of Logs: 26/Sep/2024:10:07:32.089983378 > End of Logs: 26/Sep/2024:15:54:29.895403688 > > Processed Log Time: 5 Hours, 46 Minutes, 57.805426688 Seconds > > Restarts: 0 > Secure Protocol Versions: > - TLS1.2 128-bit AES-GCM (123117 connections) > > Peak Concurrent Connections: 22 > Total Operations: 1097043 > Total Results: 1097044 > Overall Performance: 100.0% > > Total Connections: 128646 (6.18/sec) (370.78/min) > - LDAP Connections: 128646 (6.18/sec) (370.78/min) > - LDAPI Connections: 0 (0.00/sec) (0.00/min) > - LDAPS Connections: 0 (0.00/sec) (0.00/min) > - StartTLS Extended Ops: 123116 (5.91/sec) (354.84/min) > > Searches: 845279 (40.60/sec) (2436.22/min) > Modifications: 0 (0.00/sec) (0.00/min) > Adds: 0 (0.00/sec) (0.00/min) > Deletes: 0 (0.00/sec) (0.00/min) > Mod RDNs: 0 (0.00/sec) (0.00/min) > Compares: 0 (0.00/sec) (0.00/min) > Binds: 128647 (6.18/sec) (370.78/min) > > Average wtime (wait time): 0.001560856 > Average optime (op time): 0.003310453 > Average etime (elapsed time): 0.004868040 > > Multi-factor Authentications: 0 > Proxied Auth Operations: 0 > Persistent Searches: 0 > Internal Operations: 0 > Entry Operations: 0 > Extended Operations: 123116 > Abandoned Requests: 1 > Smart Referrals Received: 0 > > VLV Operations: 0 > VLV Unindexed Searches: 0 > VLV Unindexed Components: 0 > SORT Operations: 0 > > Entire Search Base Queries: 0 > Paged Searches: 0 > Unindexed Searches: 0 > Unindexed Components: 0 > Invalid Attribute Filters: 0 > FDs Taken: 128646 > FDs Returned: 129318 > Highest FD Taken: 968 > > Broken Pipes: 0 > Connections Reset By Peer: 0 > Resource Unavailable: 0 > Max BER Size Exceeded: 0 > > Binds: 128647 > Unbinds: 119206 > ------------------------------------- > - LDAP v2 Binds: 0 > - LDAP v3 Binds: 128647 > - AUTOBINDs(LDAPI): 0 > - SSL Client Binds: 0 > - Failed SSL Client Binds: 0 > - SASL Binds: 0 > - Dir

4 4

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

2005

389-users October 2024