Bug 1003011
Summary: | suboptimal nslcd protocol handling, spammy /var/log/messages | ||
---|---|---|---|
Product: | [Fedora] Fedora | Reporter: | John Sullivan <jsrhbz> |
Component: | nss-pam-ldapd | Assignee: | Nalin Dahyabhai <nalin> |
Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
Severity: | unspecified | Docs Contact: | |
Priority: | unspecified | ||
Version: | 18 | CC: | arthur, jhrozek, jsrhbz, lslebodn, nalin |
Target Milestone: | --- | ||
Target Release: | --- | ||
Hardware: | Unspecified | ||
OS: | Unspecified | ||
Whiteboard: | |||
Fixed In Version: | nss-pam-ldapd-0.8.13-4.fc20 | Doc Type: | Bug Fix |
Doc Text: | Story Points: | --- | |
Clone Of: | Environment: | ||
Last Closed: | 2013-10-18 19:36:28 UTC | Type: | Bug |
Regression: | --- | Mount Type: | --- |
Documentation: | --- | CRM: | |
Verified Versions: | Category: | --- | |
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
Cloudforms Team: | --- | Target Upstream Version: | |
Embargoed: |
Description
John Sullivan
2013-08-30 13:31:49 UTC
Interesting, thank you for the bug report. I was under the impression that the problem was already fixed in that version. Yes, according to the -users thread above, *a* fix was put into 0.8.7. It's just not a good enough fix. (Hmm. Perhaps it mostly works on a heavily loaded or single-core machine, where the write sequence isn't expected to get preempted by the read sequence. With two free running cores on this 8-core machine, the race loses all the time!) Thanks for your detailed analysis and comments. Regarding 1) I think it is an excellent proposal to avoid more of the broken pipe errors. I will add a short timeout of 500 msec because the request will probably be repeated a number of times and having a longer timeout could ensure in the application hanging longer if something goes wrong. Regarding 2) I agree that the broken pipe error is, in general, not always an indication that something is terribly wrong. On the other hand it is a indication that a request was broken off. Anyway, I haven't seen a "real" problem that caused the EPIPE error in a long time so I think it should be reasonably safe to ignore. I'm going to include both changes in the next 0.9 upstream release and may also include the changes in a next 0.8 release. Thanks Thank you very much for looking into this, Arthur. I'll be happy to test these patches as well. The change for 1) is here: http://arthurdejong.org/git/nss-pam-ldapd/commit/?id=c9e2f9778e9267348bdfa4bf2a8d950bcf5fbd The change for 2) is here: http://arthurdejong.org/git/nss-pam-ldapd/commit/?id=4897033a912d513be82268b20fe73190684960 I've only done some quick testing so feedback is very much appreciated. That'll work most of the time, but the timeout can fail in clients using fast periodic SIGALRMs for their own purposes (the resulting EINTR resets to the full timeout each time.) There is existing logic in tio.c to handle this using tio_get_deadline/tio_time_remaining. (As a complete sidenote, timeouts using gettimeofday() are inherently unreliable in the face of system clock changes, and though tio_wait attempts to handle this by clamping the residual to the total timeout, a better way is to use clock_gettime(CLOCK_MONOTONIC) instead. And again, in the face of fast periodic SIGALRMs the clamping will have no effect.) (Oh, and it looks like the EINTR/EAGAIN check in tio_read() can drop through and leave -1 in readbuffer.len, which being declared a size_t within tio_buffer earlier in tio.c will "pass" the readbuffer.len>=count check next time round the loop and copy an inexhaustible supply of garbage into the client's buffer. Or segfault. Unlikely to hit if poll() has just returned immediate readability, but still possible perhaps.) In the 0.9 series the tio_get_deadline() function was replaced, mainly to reduce the number of calls to gettimeofday() changing some bits of the code. I've had a look at also using tio_wait() inside tio_skipall() and that isn't too difficult (actually it results in much cleaner code). Switching to clock_gettime(CLOCK_MONOTONIC) also seams easy but I want to test portability affects of that change before merging. Thanks for pointing it out. Thanks for pointing out the EINTR/EAGAIN problem in tio_read(). Fixes for this have been committed and I will probably make new releases soonish with the fixes. I agree that is unlikely to to happen and I don't think this can be triggered maliciously. Thanks again for your valuable feedback. (In reply to Arthur de Jong from comment #7) > In the 0.9 series the tio_get_deadline() function was replaced, mainly to > reduce the number of calls to gettimeofday() changing some bits of the code. On a similar vein to this, I noticed from the straces that nslcd always writes in 64 byte chunks, even though it must have pretty much all the data up front and therefore "know" how much there is, which means we're needlessly repeating poll/write in nslcd and gettimeofday/poll/read. (Well, instrumenting shows tio_write() called with lots of 3-11 byte chunks, so it doesn't know the total size up front, but is constructing the response without extra waits, I think.) It looks like nslcd allows up to a 1MB buffer, but that tio will only grow the buffer from the initial 64 byte guess if an attempt to do the non-blocking write fails, but since the client is spinning on poll/read just as fast as nslcd can send the data (and in any case the underlying channel buffer is much larger than the total amount of data we're writing), this never happens. (Another point here: the client end (common/nslcd-prot.c) uses an initial buffer of 1024 bytes with a max of 2MB, which seems oddly inconsistent.) The initial nslcd writebuffer.size could be made larger, and/or we could always add the new data to the buffer if size<maxsize and not flush unless we hit maxsize or the caller flushes at the end of message. (I suspect many users will frequently hit a small number of kB, but hitting 1MB is much rarer. In any case, the local malloc/memcpy overhead is likely to be much less than the syscall overhead of lots of small writes.) The 0.9.0 version of nss-pam-ldapd has already seen a few improvements in the communications handling to reduce the number of system calls. The main reason that nslcd has a large write buffer is to handle slow NSS calls while reading as much data from the LDAP server as possible. For example, an application could call setpwent(), getpwent(), do stuff, getpwent(), do more stuff, etc. The application could be slow between getpwent() calls or the LDAP server could be slow in returning entries. The buffer handling probably isn't ideal but it works reasonably well and seems to balance returning (partial) data quickly to the requesting application and doing buffering when needed. We could go with a larger write buffer to start off with. One average passwd entry could be around 64 bytes in size. Waiting for four entries from LDAP before starting to write to the caller is probably OK. Originally it was also an idea to hand off the flushing of the buffer to a separate thread that would write any remaining data in the buffers, so the worker thread would be available again to handle requests. The reason that the client buffer is larger (at least the max) is to support retries of getgrent(). For groups with a lot of users, the function will be called (by libc) with a too small buffer and it will retry until the buffer is large enough. If we are going over the groups we can't easily restart the whole request so we do the equivalent of a seek() in the stream back to the beginning of the group entry. Groups that are bigger than 2MB are too big anyway. Thanks again for your comments. nss-pam-ldapd-0.8.13-3.fc19 has been submitted as an update for Fedora 19. https://admin.fedoraproject.org/updates/nss-pam-ldapd-0.8.13-3.fc19 nss-pam-ldapd-0.8.13-4.fc20 has been submitted as an update for Fedora 20. https://admin.fedoraproject.org/updates/nss-pam-ldapd-0.8.13-4.fc20 nss-pam-ldapd-0.8.13-3.fc18 has been submitted as an update for Fedora 18. https://admin.fedoraproject.org/updates/nss-pam-ldapd-0.8.13-3.fc18 Package nss-pam-ldapd-0.8.13-4.fc20: * should fix your issue, * was pushed to the Fedora 20 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing nss-pam-ldapd-0.8.13-4.fc20' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-18412/nss-pam-ldapd-0.8.13-4.fc20 then log in and leave karma (feedback). nss-pam-ldapd-0.8.13-3.fc18 tested, and appears to resolve issue. Thanks! Thank you for testing and working with Arthur towards a good solution! nss-pam-ldapd-0.8.13-3.fc19 has been pushed to the Fedora 19 stable repository. If problems still persist, please make note of it in this bug report. nss-pam-ldapd-0.8.13-3.fc18 has been pushed to the Fedora 18 stable repository. If problems still persist, please make note of it in this bug report. nss-pam-ldapd-0.8.13-4.fc20 has been pushed to the Fedora 20 stable repository. If problems still persist, please make note of it in this bug report. |