Hi all,
Just curious if anyone has suggestions about that please before I get
going in a couple of hours with conversions to IPA again? I did the math
and 1,097,471 log messages in 5 hours is about 60 times per second, so
I'm gradually becoming more certain this is why we can only boot 20-30
nodes at a time when we used to boot hundreds. However, this is still
just a guess as I don't know the mechanism behind why this interferes
with IPA joins, some bottleneck with the KDC?
It sure seems like this is a kerberized NFS request for a host that
doesn't provide it, or doesn't have an nfs principal. I think you'd need
to monitor the offending client to see what it is doing.
If the KDC is being dramatically slowed down by this then yes, you could
see slower Apache performance because it needs to obtain tickets on
behalf of the user doing the join. Whether that would represent itself
as a read timeout I don't know.
rob
Alfred
On Wed, Jun 9, 2021 at 3:49 PM Alfred Victor <alvic266(a)gmail.com
<mailto:alvic266@gmail.com>> wrote:
Hi Rob,
I have reduced that timeout and will tune it further. Regarding ISE
errors, I think we can make the assumption that this is entirely an
issue of the web timeouts, I haven't seen any evidence otherwise and
will have another attempt at converting nodes tomorrow, and with a
keener eye of what to look for I can make a better determination
then. I am most concerned over what the underlying cause might be
causing it to take too long and hit the timeout, and don't want to
engineer around this by changing Apache timeouts if we can instead
address the root cause. I am suspicious of krb log messages flooding
our IPA systems about a service principal like so, but not sure if
this is gumming up the works (or even why this message has started
appearing since the rebuild):
./krb5kdc.log:Jun 09 10:38:51
redacted.redacted.com
<
http://redacted.redacted.com> krb5kdc[31187](info): TGS_REQ (4 etypes {18 17 16
23}) 10.1.1.27 <
http://10.1.1.27>: LOOKING_UP_SERVER: authtime 0,
host/redacted.redacted.com(a)redacted.COM for nfs/nfsserver.redacted.com(a)redacted.COM,
Server not found in Kerberos database
Just in the last 5 hours alone, this log message and others like it (main difference
is just the nodename it references) has appeared 1,097,471 times. Conceivably there is
also some log write locking or something going on that could be slowing IPA down and
leading to our symptom here?
Alfred
On Wed, Jun 9, 2021 at 9:19 AM Rob Crittenden <rcritten(a)redhat.com
<mailto:rcritten@redhat.com>> wrote:
Alfred Victor wrote:
> Hi Rob,
>
> We did revert to 60s - I seem to remember some ldapsearch
timing out
> previously but maybe we could still greatly reduce this with
no ill
> effect. However, we saw no change in join success either way
and I have
> not changed anything in Apache as I would need to find the
exact values
> in question and I think these directive changes may get lost
with an
> update? The timeout/ISE issues are new - we previously booted
many nodes
> concurrently (400+) without problems but now it happens even
booting as
> few as 50 results in 10-20 timeouts or ISE. This has been the
case at
> least since we rebuilt and re-replicated the environment by
swapping IPA
> members out of the old one, but maybe this is unrelated. Is it
possible
> we landed on a newer version with different timeout values? Is it
> possible that IPA is under slightly more load from the higher
number of
> nodes and has some bottleneck since we last did conversions?
We have not
> been able to substantiate the latter by looking at
CPU/memory/io trends.
> What might we investigate next to see if we may have missed
some ongoing
> issue that could for instance cause locking problems or
something else
> internally in IPA to explain our symptoms? Also, I have
observed some
> nodes which report a successful installation of IPA client,
but have in
> fact a lot of failures, for instance with mounts not working from
> automount setup. We will need to try to reproduce this to
understand
> what happened I think as we have already sorted those nodes
elsewhere
> and they have got going outside of IPA.
>
> I am interested that you suggested "at least some of the
clients aren't
> connecting at all and increasing the timeout could make this
worse" -
> this might indicate some sort of network problem at play, but
as far as
> I am aware, everything is working absent IPA so I do not
suspect it
> presently.
A 60 second LDAP timeout is still way too big. The default is 2.
Unless
you are seeing timeouts I'd suggest lowering it.
I'm only seeing hints to what you're seeing and the scope so
it's hard
to make further suggestions. Are all the internal errors the
same, for
example? Are some failing due to LDAP timeouts or are they all
wsgi read
timeouts?
The Apache request timeout can be configured in httpd.conf which is
independent of the config files that IPA currently writes so it
should
survive upgrades.
rob
>
> Alfred
>
> On Mon, Jun 7, 2021 at 4:42 PM Rob Crittenden
<rcritten(a)redhat.com <mailto:rcritten@redhat.com>
> <mailto:rcritten@redhat.com <mailto:rcritten@redhat.com>>>
wrote:
>
> Alfred Victor wrote:
> > Actually, no change happened from 300-> 600 timeout, the
web portal
> > itself gave me an ISE I hadn't noticed when I tried
clicking save!
>
> I wasn't clear which log to look in. You'll see details
about where the
> error is caught in IPA in the Apache log. To see LDAP
timeouts you look
> for err=3 in the 389-ds access log.
>
> But since you posted a traceback this time it's clear that
this is just
> Apache waiting for client data to read so any tuning you
do needs to be
> in Apache. You could try tuning Timeout which defaults to
60 but this
> doesn't seem likely to help since at least some of the
clients aren't
> connecting at all and increasing the timeout could make
this worse.
>
> Please revert the searchtimeout. 300 seconds is orders of
magnitude
> too big.
>
> rob
>
> >
> > Alfred
> >
> > On Mon, Jun 7, 2021 at 3:57 PM Alfred Victor
<alvic266(a)gmail.com <mailto:alvic266@gmail.com>
> <mailto:alvic266@gmail.com <mailto:alvic266@gmail.com>>
> > <mailto:alvic266@gmail.com <mailto:alvic266@gmail.com>
<mailto:alvic266@gmail.com <mailto:alvic266@gmail.com>>>>
wrote:
> >
> > Hi FreeIPA list,
> >
> > I don't see any in error log that match `grep -i
"err=3"
> > /var/log/httpd/error_log`. We have tried raising
> searchtimelimit as
> > high as 120, then 300 (now are trying 600) but
observed no
> > difference in the rate at which nodes succeeded or
failed in IPA
> > joins. We are somewhat puzzled by this, as none of
the other
> values
> > we are aware of might have changed, though it is
possible that the
> > IPA systems are under a little higher demand from client
> systems, we
> > have tried to mitigate this by shutting down some
workflows and
> > aren't sure whether we've seen any improvement.
Short of adjusting
> > apache/resource/process timeouts it is difficult to
say what might
> > be wrong. To give an example, out of 250 nodes
rebooted, only 112
> > joined IPA successfully. Here is some output from
the error log,
> > following what this looks like in the ipa client
install log
> (error
> > log output will match the node attempt):
> >
> >
> > 2021-06-07T18:25:30Z DEBUG The ipa-client-install
command
> failed, exception: NetworkError: cannot connect to
> 'https://redactednode.com/ipa/json
> <https://hauth0004.dug.com/ipa/json>': Internal Server Error
> >
> > [Mon Jun 07 13:25:06.198259 2021] [core:error] [pid
25020]
> [client 10.1.24.48:47808 <
http://10.1.24.48:47808>
<
http://10.1.24.48:47808>
> <http://10.1.24.48:47808>] Script timed out before returning
> headers: wsgi.py, referer:
https://redacted.redacted.com/ipa/xml
> <https://hauth0004.dug.com/ipa/xml>
> >
> > Different node, same time period:
> >
> >
> > [Mon Jun 07 13:24:02.178092 2021] [:error] [pid
25725] ipa:
> INFO: [xmlserver] mach_join(a)redacted.COM:
join(u'redacted.node.com <
http://redacted.node.com>
> <http://redacted.node.com> <
http://redacted.node.com>';,
> nshardwareplatform=u'x86_64',
> nsosversion=u'3.10.0-1062.18.1.1.el7.redacted.x86_64',
> version=u'2.51'): TimeLimitExceeded
> >
> > I also saw this:
> >
> > [Mon Jun 07 13:25:07.103503 2021] [:error] [pid
25725] ipa:
> ERROR: non-public: IOError: request data read error
> > [Mon Jun 07 13:25:07.103529 2021] [:error] [pid 25725]
> Traceback (most recent call last):
> > [Mon Jun 07 13:25:07.103536 2021] [:error] [pid
25725] File
> "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py",
line 360,
> in wsgi_execute
> > [Mon Jun 07 13:25:07.103542 2021] [:error] [pid
25725]
> data = read_input(environ)
> > [Mon Jun 07 13:25:07.103548 2021] [:error] [pid
25725] File
> "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py",
line 200,
> in read_input
> > [Mon Jun 07 13:25:07.103553 2021] [:error] [pid
25725]
> return
environ['wsgi.input'].read(length).decode('utf-8')
> > [Mon Jun 07 13:25:07.103559 2021] [:error] [pid 25725]
> IOError: request data read error
> > [Mon Jun 07 13:25:07.103826 2021] [:error] [pid
25725] ipa:
> INFO: [xmlserver] mach_join(a)redacted.COM: None: InternalError
> > [Mon Jun 07 13:25:07.149962 2021] [:error] [pid
25726] ipa:
> ERROR: non-public: IOError: request data read error
> > [Mon Jun 07 13:25:07.149984 2021] [:error] [pid 25726]
> Traceback (most recent call last):
> > [Mon Jun 07 13:25:07.149991 2021] [:error] [pid
25726] File
> "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py",
line 360,
> in wsgi_execute
> > [Mon Jun 07 13:25:07.149997 2021] [:error] [pid
25726]
> data = read_input(environ)
> > [Mon Jun 07 13:25:07.150002 2021] [:error] [pid
25726] File
> "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py",
line 200,
> in read_input
> > [Mon Jun 07 13:25:07.150008 2021] [:error] [pid
25726]
> return
environ['wsgi.input'].read(length).decode('utf-8')
> > [Mon Jun 07 13:25:07.150013 2021] [:error] [pid 25726]
> IOError: request data read error
> >
> >
> >
> > After setting the timeout to 600 and rebooting the
remaining
> 139 nodes from the initial set of 250, 83 joined of the
139 and we
> still had ISE occurring. In some cases, it would ISE on
the first
> attempt, try another IPA system, and succeed. I'm not sure
that even
> such a long timeout as 600 has helped.
> >
> > Alfred
> >
> >
> >
> >
> > On Thu, Jun 3, 2021 at 7:51 PM Rob Crittenden
> <rcritten(a)redhat.com <mailto:rcritten@redhat.com>
<mailto:rcritten@redhat.com <mailto:rcritten@redhat.com>>
> > <mailto:rcritten@redhat.com
<mailto:rcritten@redhat.com> <mailto:rcritten@redhat.com
<mailto:rcritten@redhat.com>>>> wrote:
> >
> > Alfred Victor via FreeIPA-users wrote:
> > > Hi FreeIPA list,
> > >
> > > We are having an issue with our IPA
environment of 4
> > replicated FreeIPA
> > > systems serving linux compute clients
which join from a
> command in
> > > rc.local after boot. This worked in the past,
but the system
> > has been
> > > rebuilt since and the join command changed
> slightly. Unfortunately
> > > booting a few dozen nodes at a time, though
they each
> talk to a
> > > different IPA system by design, leads to
problems such as
> > these - though
> > > 40-100 nodes can boot ok at a time there are
always many
> > stragglers, and
> > > the more we attempt to boot at once the more
fail to
> join IPA
> > (if we try
> > > to boot 500 nodes, we are lucky if we get a
fifth of that
> > joining IPA).
> > > Can you please advise on this output? Here is
our join
> command in
> > > compute node rc.local:
> > >
> > >
> > >
> > > ipa-client-install -U -q -p mach_join \
> > > -w <redacted> \
> > > --force-join \
> > > --no-dns-sshfp \
> > > --automount-location=redacted-node
> > >
> > >
> > >
> > >
> > > And here is some log output of the 500 error:
> > >
> > > ProtocolError: <ProtocolError for
> > redacted.redacted.com/ipa/json
<
http://redacted.redacted.com/ipa/json>
> <http://redacted.redacted.com/ipa/json>
> > <http://redacted.redacted.com/ipa/json>
> > <http://redacted.redacted.com/ipa/json>: 500
Internal
> Server Error>
> > > Cannot connect to the server due to
generic error:
> cannot
> > connect to 'https://redacted.redacted.com/ipa/json
> > <https://hauth0003.dug.com/ipa/json>': Internal
Server Error
> > >
> > >
> > > As well as:
> > >
> > > 2021-06-02T21:39:11Z DEBUG Starting
external process
> > > 2021-06-02T21:39:11Z DEBUG
args=/usr/sbin/ipa-join -s
> > > redacted.redacted.com
<
http://redacted.redacted.com> <
http://redacted.redacted.com>
> <http://redacted.redacted.com>
> > <http://redacted.redacted.com> -b
> > > dc=redacted,dc=com -h
redactednode.redacted.com <
http://redactednode.redacted.com>
> <http://redactednode.redacted.com>
> > <http://redactednode.redacted.com>
> > > <http://redactednode.redacted.com> -f
> > > 2021-06-02T21:40:13Z DEBUG Process
finished, return
> code=17
> > > 2021-06-02T21:40:13Z DEBUG stdout=
> > > 2021-06-02T21:40:13Z DEBUG stderr=HTTP
response code is
> > 500, not 200
> > > 2021-06-02T21:40:13Z ERROR Joining realm
failed: HTTP
> > response code
> > > is 500, not 200
> > >
> > > And we also see timeouts happen:
> > >
> > >
> > > 2021-06-02T22:08:50Z DEBUG
args=/usr/sbin/ipa-join -s
> > > redacted.redacted.com
<
http://redacted.redacted.com> <
http://redacted.redacted.com>
> <http://redacted.redacted.com>
> > <http://redacted.redacted.com> -b
> > > dc=redacted,dc=com -h
redactednode.redacted.com <
http://redactednode.redacted.com>
> <http://redactednode.redacted.com>
> > <http://redactednode.redacted.com>
> > > <http://redactednode.redacted.com> -f
> > > 2021-06-02T22:09:01Z DEBUG Process
finished, return
> code=17
> > > 2021-06-02T22:09:01Z DEBUG stdout=
> > > 2021-06-02T22:09:01Z DEBUG stderr=RPC
failed at server.
> > Configured
> > > time limit exceeded
> > > 2021-06-02T22:09:01Z ERROR Joining realm
failed: RPC
> failed at
> > > server. Configured time limit exceeded
> > >
> > >
> > > And we also see later timeouts near the end of
the log
> in some
> > cases though are able to authenticate and it
didn't back
> out the
> > install, but never got going healthy either:
> > >
> > >
> > >
> > > 2021-06-03T19:20:13Z DEBUG The
ipa-client-install
> command
> > failed,
> > > exception: TimeLimitExceeded: Configured
time limit
> exceeded
> >
> > When you see Internal Error look to the Apache
error log
> on the
> > server
> > for more information.
> >
> > In this case an LDAP search is failing because
the server
> is too
> > busy.
> > Look for queries failing with err=3 to get an
idea of how long
> > it is taking.
> >
> > To increase the timeout use: ipa config-mod
> --searchtimelimit=INT
> >
> > The default is 2 seconds.
> >
> > You can pick a time at random but could see
failures again.
> >
> > rob
> >
>