[krbdev.mit.edu #6998] kadmin incremental propagation full resync multiple processes spawned
The RT System itself via RT
rt-comment at krbdev.mit.edu
Wed Nov 2 18:18:33 EDT 2011
>From krb5-bugs-incoming-bounces at PCH.mit.edu Wed Nov 2 18:18:32 2011
Return-Path: <krb5-bugs-incoming-bounces at 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 at 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 at 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 at 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 at 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 at 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 at mit.edu
Subject: kadmin incremental propagation full resync multiple processes spawned
From: henson at csupomona.edu
X-send-pr-version: 3.99
Message-Id: <20111102215905.F1048C003C at 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 at mailman.mit.edu
X-Mailman-Version: 2.1.6
Precedence: list
Reply-To: henson at csupomona.edu
Sender: krb5-bugs-incoming-bounces at PCH.mit.edu
Errors-To: krb5-bugs-incoming-bounces at PCH.mit.edu
>Submitter-Id: net
>Originator: Paul Henson
>Organization:
Cal Poly Pomona
>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
>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 at CSUPOMONA
.EDU, service=kiprop/kerberos-master.csupomona.edu at 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 at CSUPOMONA.EDU, service=kiprop/kerberos-master.csupomona.edu at 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 at CSUPOMONA.EDU, service=kiprop/kerberos-master.csupomona.edu at 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 at CSUPOMONA.EDU, service=kiprop/kerberos-master.csupomona.edu at 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 at CSUPOMONA.EDU, success, client=idmgmt at CSUPOMONA.EDU, service=kadmin/admin at CSUPOMONA.EDU, addr=134.71.247.23
Nov 2 03:52:14 halfy kadmind[8938]: Request: kadm5_modify_principal, daisytorres at CSUPOMONA.EDU, success, client=idmgmt at CSUPOMONA.EDU, service=kadmin/admin at 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.
>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.
>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.
>Fix:
More information about the krb5-bugs
mailing list