Hi,
I have those errors BER write errors that have crept up recently on 2 slapd providers in a mirror replication setup and I can't seem to find the cause of them. I must have made a change to the config but pea brain of me can't seem to find the root of it. They are now occurring a few times a day.
I have turned on BER, conns, stats, and sync debugging but it's still unclear to me what is going on. Can anyone shed some light?
IP=172.16.10.247 is a HAproxy server with the 2 mirrors as backends. There is also a Munin host that polls the providers every 5m or so to gather stats.
Thanks and Happy Holiday! jf
Here a anonymized excerpt of the logs of one server showing the error message:
Dec 26 03:20:45 ldap-server slapd[4306]: daemon: listen=8, new connection on 18 Dec 26 03:20:45 ldap-server slapd[4306]: daemon: added 18r (active) listener=(nil) Dec 26 03:20:45 ldap-server slapd[4306]: conn=2799347 fd=18 ACCEPT from IP=172.16.10.247:33746 (IP=0.0.0.0:389) Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on 2 descriptors Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on: Dec 26 03:20:45 ldap-server slapd[4306]: 18r Dec 26 03:20:45 ldap-server slapd[4306]: Dec 26 03:20:45 ldap-server slapd[4306]: daemon: read active on 18 Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: conn=2799347 op=0 BIND dn="" method=128 Dec 26 03:20:45 ldap-server slapd[4306]: conn=2799347 op=0 RESULT tag=97 err=0 text= Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on 1 descriptor Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on: Dec 26 03:20:45 ldap-server slapd[4306]: Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on 1 descriptor Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on: Dec 26 03:20:45 ldap-server slapd[4306]: 18r Dec 26 03:20:45 ldap-server slapd[4306]: Dec 26 03:20:45 ldap-server slapd[4306]: daemon: read active on 18 Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on 1 descriptor Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on: Dec 26 03:20:45 ldap-server slapd[4306]: Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on 1 descriptor Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on: Dec 26 03:20:45 ldap-server slapd[4306]: Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: connection_read(18): input error=-2 id=2799347, closing. Dec 26 03:20:45 ldap-server slapd[4306]: connection_closing: readying conn=2799347 sd=18 for close Dec 26 03:20:45 ldap-server slapd[4306]: daemon: removing 18 Dec 26 03:20:45 ldap-server slapd[4306]: conn=2799347 fd=18 closed (connection lost) Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on 1 descriptor Dec 26 03:20:45 ldap-server slapd[4306]: daemon: activity on: Dec 26 03:20:45 ldap-server slapd[4306]: Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 26 03:20:45 ldap-server slapd[4306]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 26 03:20:46 ldap-server slapd[4306]: daemon: activity on 1 descriptor Dec 26 03:20:46 ldap-server slapd[4306]: daemon: activity on: Dec 26 03:20:46 ldap-server slapd[4306]: 15r Dec 26 03:20:46 ldap-server slapd[4306]: Dec 26 03:20:46 ldap-server slapd[4306]: daemon: read active on 15 Dec 26 03:20:46 ldap-server slapd[4306]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 26 03:20:46 ldap-server slapd[4306]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 26 03:20:46 ldap-server slapd[4306]: daemon: epoll: listen=10 active_threads=0 tvp=zero Dec 26 03:20:46 ldap-server slapd[4306]: conn=2799050 op=3 SRCH base="dc=example,dc=com" scope=2 deref=0 filter="(&(objectClass=posixAccount)(uid=root))" Dec 26 03:20:46 ldap-server slapd[4306]: ber_flush2 failed errno=32 reason="Broken pipe" Dec 26 03:20:46 ldap-server slapd[4306]: connection_closing: readying conn=2799050 sd=15 for close Dec 26 03:20:46 ldap-server slapd[4306]: send_ldap_response: ber write failed Dec 26 03:20:46 ldap-server slapd[4306]: conn=2799050 op=3 SEARCH RESULT tag=101 err=0 nentries=0 text= Dec 26 03:20:46 ldap-server slapd[4306]: connection_resched: attempting closing conn=2799050 sd=15 Dec 26 03:20:46 ldap-server slapd[4306]: daemon: removing 15 Dec 26 03:20:46 ldap-server slapd[4306]: conn=2799050 fd=15 closed (connection lost on write)
Jean-Francois Malouin wrote:
Hi,
I have those errors BER write errors that have crept up recently on 2 slapd providers in a mirror replication setup and I can't seem to find the cause of them. I must have made a change to the config but pea brain of me can't seem to find the root of it. They are now occurring a few times a day.
I have turned on BER, conns, stats, and sync debugging but it's still unclear to me what is going on. Can anyone shed some light?
The client is closing the connection before slapd has finished sending the response. Doesn't really mean anything, besides poorly written clients on your network.
On 12/27/18 6:04 AM, Howard Chu wrote:
The client is closing the connection before slapd has finished sending the response. Doesn't really mean anything, besides poorly written clients on your network.
1. I've seen this a lot. I would say that over half of all client software LDAP interfaces I've seen do not UNBIND, then close the connection with a FIN, FINACK handshake (TCP client close).
I do not know of any impact on a server level; it just seems slopping to have in the logs, asking people to explain something that may not even be a problem. But I wonder what if any negative impact, let's say if whatever effect was multiplied many times? Clients still have to wait for 2MSL when they do a clean and proper UNBIND + TCP 3way handshake termination. Unless I am mistaken in my understanding of TCP, closing LDAP connections on a frequent basis always has some minor impact, even in the best situations, in that you have a temporarily unusable client port waiting for 2MSL to be able to be used again. Theoretically you could run out of client ports with an extremely (60K+) number of connections. This number of connections is ridiculous though, so this antipattern case may not be realistic at all.
2. I also see a lot of clients that unnecessarily open new connections and close them for every lookup (SEARCH), impolitely or politely with UNBIND/ldap.close() and this is a certain impact that multiplies and can be easily avoided by reusing connections.
CP
* Howard Chu hyc@symas.com [20181227 09:08]:
Jean-Francois Malouin wrote:
Hi,
I have those errors BER write errors that have crept up recently on 2 slapd providers in a mirror replication setup and I can't seem to find the cause of them. I must have made a change to the config but pea brain of me can't seem to find the root of it. They are now occurring a few times a day.
I have turned on BER, conns, stats, and sync debugging but it's still unclear to me what is going on. Can anyone shed some light?
The client is closing the connection before slapd has finished sending the response. Doesn't really mean anything, besides poorly written clients on your network.
Thanks for the time to answer my question!
regards, jf
-- -- Howard Chu CTO, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/
openldap-technical@openldap.org
-
Christopher Paul -
Howard Chu -
Jean-Francois Malouin