Skip Menu |
 

Download (untitled) / with headers
text/plain 7.6KiB
From krb5-bugs-incoming-bounces@PCH.mit.edu Wed Nov 2 18:18:32 2011
Return-Path: <krb5-bugs-incoming-bounces@PCH.mit.edu>
Received: from pch.mit.edu (PCH.MIT.EDU [18.7.21.90])
by krbdev.mit.edu (Postfix) with ESMTP id 29D5A3E68E;
Wed, 2 Nov 2011 18:18:32 -0400 (EDT)
Received: from pch.mit.edu (pch.mit.edu [127.0.0.1])
by pch.mit.edu (8.13.6/8.12.8) with ESMTP id pA2MIVG5007889;
Wed, 2 Nov 2011 18:18:31 -0400
Received: from mailhub-dmz-2.mit.edu (MAILHUB-DMZ-2.MIT.EDU [18.7.62.37])
by pch.mit.edu (8.13.6/8.12.8) with ESMTP id pA2LxvDE005782
for <krb5-bugs-incoming@PCH.mit.edu>; Wed, 2 Nov 2011 17:59:57 -0400
Received: from dmz-mailsec-scanner-8.mit.edu (DMZ-MAILSEC-SCANNER-8.MIT.EDU
[18.7.68.37])
by mailhub-dmz-2.mit.edu (8.13.8/8.9.2) with ESMTP id pA2LxlFf002909
for <krb5-bugs@mit.edu>; Wed, 2 Nov 2011 17:59:57 -0400
X-AuditID: 12074425-b7f116d0000008fe-00-4eb1bd5c0ad7
Authentication-Results: symauth.service.identifier
Received: from ironport01-1.csupomona.edu (ironport01-1.csupomona.edu
[134.71.187.41])
by dmz-mailsec-scanner-8.mit.edu (Symantec Messaging Gateway) with SMTP
id 98.BA.02302.D5DB1BE4; Wed, 2 Nov 2011 17:59:57 -0400 (EDT)
X-IronPort-Anti-Spam-Filtered: true
X-IronPort-Anti-Spam-Result: AvwEAIa8sU6GR/cT/2dsb2JhbABEDqlmgQWCGFGBFiUfnSOXH4kEg0OEbGEEiAeMDZEuVw
Received: from sparky.unx.csupomona.edu ([134.71.247.19])
by ironport01-2.csupomona.edu with ESMTP; 02 Nov 2011 14:59:06 -0700
Received: from localhost (localhost [127.0.0.1])
by sparky.unx.csupomona.edu (Postfix) with ESMTP id 3D804DC054
for <krb5-bugs@mit.edu>; Wed, 2 Nov 2011 14:59:06 -0700 (PDT)
X-Virus-Scanned: amavisd-new at csupomona.edu
Received: from sparky.unx.csupomona.edu ([127.0.0.1])
by localhost (sparky.unx.csupomona.edu [127.0.0.1]) (amavisd-new,
port 10024) with ESMTP id HiZReVS-ZaYX for <krb5-bugs@mit.edu>;
Wed, 2 Nov 2011 14:59:06 -0700 (PDT)
Received: from halfy.unx.csupomona.edu (halfy.unx.csupomona.edu [134.71.247.9])
by sparky.unx.csupomona.edu (Postfix) with ESMTP id 23C5EDC047
for <krb5-bugs@mit.edu>; Wed, 2 Nov 2011 14:59:06 -0700 (PDT)
Received: by halfy.unx.csupomona.edu (Postfix, from userid 1005)
id F1048C003C; Wed, 2 Nov 2011 14:59:05 -0700 (PDT)
To: krb5-bugs@mit.edu
Subject: kadmin incremental propagation full resync multiple processes spawned
From: henson@csupomona.edu
X-send-pr-version: 3.99
Message-Id: <20111102215905.F1048C003C@halfy.unx.csupomona.edu>
Date: Wed, 2 Nov 2011 14:59:05 -0700 (PDT)
X-Brightmail-Tracker: H4sIAAAAAAAAA+NgFlrGKsWRWlGSWpSXmKPExsXS5r5bUzd270Y/g2lTZC0aHh5nd2D0aDpz
lDmAMYrLJiU1J7MstUjfLoEr4/fCq4wFbxQqVp2ZydzAuFymi5GTQ0LAROLs9L1sIDajgJHE
7nOvWCHiYhIX7q0HinNxCAncZ5S4N3c/VEJZYt3Gf+wQdrLEktXr2SGKGhkltm1pZIVwNjFK
nFu3lxmiSlfi+Zs5YN1CAo8ZJW48g+q4yCgx4doSJohEucTcDb1gRSICohIv/x5jAbGFBfwk
3jzcBBZnE5CSWLTjARtEvZzEvgUbwGqYBVgk/ryBsCUExCV2bD8Ndh6vgL3E6ncPwXpZBLQl
Th/9xziBUWQBI8MqRtmU3Crd3MTMnOLUZN3i5MS8vNQiXQu93MwSvdSU0k2MwIAVYndR3cE4
4ZDSIUYBDkYlHt7Eoo1+QqyJZcWVuYcYJTmYlER5efcAhfiS8lMqMxKLM+KLSnNSiw8xSnAw
K4nwWk0DyvGmJFZWpRblw6SkOViUxHlf73DwExJITyxJzU5NLUgtgskycbAfYpTh4FCS4D0N
MlmwKDU9tSItM6cEWQ0niOACWcMDtOYwSCFvcUFibnFmOkTRKUZdjm+rFpxiFGLJy89LlRLn
nQZSJABSlFGaBzcMlHzq////f4lRVkqYl5GBgUGIB+gaYCAg5EHJ6xWjODAAhHl3g0zhycwr
gdv0CugIJqAjZl5aD3JESSJCSqqBsfgWN4vensdiE/Qux90X4zS46Pg9NTjtgsacTNvalg5m
7r1qvI68YYIXxMXmxjqrvVpwjb0quPFizT35U3e+LfPrjuvbrz99ySIupcoA92WzZt52sH1n
odD92uV8BKPb88zyvsyVRvZPz2sI/bE+lsntdS9ia/MJwTq12BON65g3+9fVdDxSYinOSDTU
Yi4qTgQApVlDWTkDAAA=
X-Mailman-Approved-At: Wed, 02 Nov 2011 18:18:30 -0400
X-BeenThere: krb5-bugs-incoming@mailman.mit.edu
X-Mailman-Version: 2.1.6
Precedence: list
Reply-To: henson@csupomona.edu
Sender: krb5-bugs-incoming-bounces@PCH.mit.edu
Errors-To: krb5-bugs-incoming-bounces@PCH.mit.edu


Show quoted text
>Submitter-Id: net
>Originator: Paul Henson
>Organization:
Cal Poly Pomona
Show quoted text
>Confidential: no
>Synopsis: kadmin incremental propagation full resync multiple processes spawned
>Severity: serious
>Priority: medium
>Category: krb5-admin
>Class: sw-bug
>Release: 1.9.1
>Environment:

System: Linux halfy 2.6.37-gentoo-r4 #6 SMP Thu Sep 15 12:28:52 PDT 2011 x86_64 Dual Core AMD Opteron(tm) Processor 280 AuthenticAMD GNU/Linux


Show quoted text
>Description:
After upgrading to 1.9.1, we've noticed that when a full resync is required kadmind behaves
unexpectedly, spawning multiple processes to handle the same resync request, and ending up
with multiple processes providing kadmin services. I'm not sure if this happens every full
resync, but it has occurred multiple times.

It starts off with a full resync request:

Nov 2 03:49:58 halfy kadmind[8938]: Request: iprop_get_updates_1, UPDATE_FULL_RESYNC_NEEDED; Incomi
ng SerialNo=102280; Outgoing SerialNo=N/A, success, client=kiprop/loogie.unx.csupomona.edu@CSUPOMONA
.EDU, service=kiprop/kerberos-master.csupomona.edu@CSUPOMONA.EDU, addr=134.71.247.11

A child process is spawned to serve that request:

Nov 2 03:49:58 halfy kadmind[8938]: Request: iprop_full_resync_1, spawned resync process 20238, client=kiprop/loogie.unx.csupomona.edu@CSUPOMONA.EDU, service=kiprop/kerberos-master.csupomona.edu@CSUPOMONA.EDU, addr=134.71.247.11

That process gets a strange error (which I'm not sure is relevant):

Nov 2 03:50:06 halfy kadmind[20238]: iprop_full_resync_1: pclose(popen) failed: Success

Then, rather than fulfilling the sync request, the child process spawns *another* child process:

Nov 2 03:52:56 halfy kadmind[20238]: Request: iprop_get_updates_1, UPDATE_FULL_RESYNC_NEEDED; Incoming SerialNo=102280; Outgoing SerialNo=N/A, success, client=kiprop/loogie.unx.csupomona.edu@CSUPOMONA.EDU, service=kiprop/kerberos-master.csupomona.edu@CSUPOMONA.EDU, addr=134.71.247.11
Nov 2 03:52:56 halfy kadmind[20238]: Request: iprop_full_resync_1, spawned resync process 20610, client=kiprop/loogie.unx.csupomona.edu@CSUPOMONA.EDU, service=kiprop/kerberos-master.csupomona.edu@CSUPOMONA.EDU, addr=134.71.247.11

There are no messages from that pid, and it seems to actually fulfill the sync request.

At this point, *two* separate kadmind processes both seem to be fulfilling kadmin requests:

Nov 2 03:52:14 halfy kadmind[20238]: Request: kadm5_get_principal, daisytorres@CSUPOMONA.EDU, success, client=idmgmt@CSUPOMONA.EDU, service=kadmin/admin@CSUPOMONA.EDU, addr=134.71.247.23
Nov 2 03:52:14 halfy kadmind[8938]: Request: kadm5_modify_principal, daisytorres@CSUPOMONA.EDU, success, client=idmgmt@CSUPOMONA.EDU, service=kadmin/admin@CSUPOMONA.EDU, addr=134.71.247.23

The last time this happened, multiple generations of children were spawned, and there were half
a dozen or so kadmind processes all serving requests.

On the kdc client side:

Nov 2 03:50:28 loogie kpropd[2911]: /usr/sbin/kpropd: Bad file descriptor while accepting connection
Nov 2 03:51:08 loogie kpropd[2911]: /usr/sbin/kpropd: Bad file descriptor while accepting connection
Nov 2 03:52:28 loogie kpropd[2911]: /usr/sbin/kpropd: Bad file descriptor while accepting connection
Nov 2 03:52:28 loogie kpropd[2911]: kpropd: Full resync, invalid return.
Nov 2 03:53:00 loogie kpropd[4221]: Connection from halfy.unx.csupomona.edu

kpropd complains about the failures and then works eventually.

Show quoted text
>From a client perspective, connections to kadmind start flaking out:

Nov 2 03:50:07 derp idmgmt[30265]: error storing expiration: Communication failure with server (Kerberos)
Nov 2 03:50:14 derp idmgmt[30265]: error storing expiration: Communication failure with server (Kerberos)
[...]
Nov 2 04:03:13 derp idmgmt[30265]: error getting principal: Communication failure with server (Kerberos)

We originally deployed incremental under 1.8, and this never happened. It seems to be something new
with 1.9.

Show quoted text
>How-To-Repeat:
Make kadmind too busy to the point where it won't serve incremental updates and force the client
to request a full sync. I'm not sure if it happens every time but it's happened multiple times.
Show quoted text
>Fix:
Subject: partially fixed by #7000
The patch in bug #7000 should solve the problem with multiple processes. Leaving this bug
open for the locking acquisition and logging clarity issues.