Bug 593904

Summary: Reconfiguring while service active spews to /var/log/messages
Product: [Fedora] Fedora Reporter: Jonathan Larmour <jifl-bugzilla>
Component: xinetdAssignee: Jan Zeleny <jzeleny>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 12CC: jzeleny
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: xinetd-2.3.14-32.fc13 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 599509 (view as bug list) Environment:
Last Closed: 2010-06-22 17:14:15 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 599509, 754444    
Attachments:
Description Flags
GNU screen log none

Description Jonathan Larmour 2010-05-20 02:42:25 UTC 
Description of problem:

I disabled the amanda backup client service with "chkconfig amanda off" while the amanda client was running. The outcome was that xinetd got itself confused and spewed this message endlessly to /var/log/messages:

May 20 02:39:03 localhost xinetd[17737]: 1 descriptors still set

By the time I noticed the log file was over 2 gig.

Here is the output in /var/log/messages when the chkconfig was run:

May 20 02:00:03 localhost xinetd[17737]: START: amanda pid=10697 from=::ffff:192.168.7.11
May 20 02:39:02 localhost xinetd[17737]: Starting reconfiguration
May 20 02:39:02 localhost xinetd[17737]: Swapping defaults
May 20 02:39:02 localhost xinetd[17737]: readjusting service tftp
May 20 02:39:02 localhost xinetd[17737]: Sending signal 9 to amanda server 10697
May 20 02:39:03 localhost xinetd[17737]: EXIT: amanda status=0 pid=10697 duration=2340(sec)
May 20 02:39:03 localhost xinetd[17737]: service amanda deactivated
May 20 02:39:03 localhost xinetd[17737]: amanda: svc_release with 0 count
May 20 02:39:03 localhost xinetd[17737]: Reconfigured: new=0 old=1 dropped=1 (services)
May 20 02:39:03 localhost xinetd[17737]: unknown child process 10697 died
May 20 02:39:03 localhost xinetd[17737]: 1 descriptors still set
[repeat forever]

I have a suspicion the problem may be because xinetd is expecting the socket to get freed up when it kills the process. However amanda forks off child processes, each of which I suspect get dups of the socket fds which they don't close (very probably for a good reason). The amanda client is of course entitled to do this, so it is xinetd which is making false assumptions.

And it should definitely not be the case that it should syslog a message repeatedly forever. This could have DoS'd my machine.

Version-Release number of selected component (if applicable):

xinetd-2.3.14-30.fc12.x86_64

Steps to reproduce:

1. Have amanda backup in progress
2. While client is running, run: chkconfig amanda off.

If my suspicions are correct, you could instead substitute any xinetd client which forks a child.
Comment 1 Jan Zeleny 2010-05-20 06:40:48 UTC 
Are you sure with the xinetd version? Revision 30 should fix this issue.
Comment 2 Jonathan Larmour 2010-05-20 08:26:05 UTC 
Yes I'm sure, and rpm -V xinetd confirms. And to check it isn't jsut the running executable not matching the RPM, I double-checked and it was installed on my machine on April 20th, and it had restarted at least on May 13th.

I've now found bug 573764 which you are evidently referring to. If I try and reproduce the problem reported in that bug report, then it does not reproduce. Similarly I can enable and disable the amanda service normally. I believe the problem is specific to when a client like the amanda client is running at the time it is disabled.

Here's a clearer way to reproduce using amanda:

1) chkconfig amanda on
2) In another shell do:
nc -u localhost 10080
3) press return so that a packet is sent and xinetd kicks off amandad
4) Back in the root shell, run: chkconfig amanda off
5) tail /var/log/messages
Comment 3 Jan Zeleny 2010-05-20 08:37:41 UTC 
Thanks for verbose information. I'll look to it ASAP.
Comment 4 Jan Zeleny 2010-05-27 11:47:39 UTC 
I didn't manage to reproduce the issue, so I might need some help here. This is my tail /var/log/messages:

May 27 13:41:17 localhost xinetd[6481]: Reconfigured: new=0 old=1 dropped=0 (services)
May 27 13:41:21 localhost xinetd[6481]: START: amanda pid=6489 from=::ffff:127.0.0.1
May 27 13:41:51 localhost xinetd[6481]: EXIT: amanda status=0 pid=6489 duration=30(sec)
May 27 13:41:59 localhost xinetd[6481]: Starting reconfiguration
May 27 13:41:59 localhost xinetd[6481]: Swapping defaults
May 27 13:41:59 localhost xinetd[6481]: service amanda deactivated
May 27 13:41:59 localhost xinetd[6481]: amanda: svc_release with 0 count
May 27 13:41:59 localhost xinetd[6481]: Reconfigured: new=0 old=0 dropped=1 (services)

Please run xinetd in debug mode (-d), try to reproduce the issue and send me the log output. Hopefully from it I will be able to find out what's wrong.
Comment 5 Jonathan Larmour 2010-05-27 16:32:35 UTC 
Created attachment 417301 [details]
GNU screen log

It reproduces so easily for me I'm surprised you have a difference. But sure, here's the debug output. I had to use GNU screen to log it (xinetd seems to send debug output straight to the tty, rather than stdout/err).
Comment 6 Jan Zeleny 2010-06-01 12:26:30 UTC 
I finally figured out what's going on. I've created a scratch build and briefly tested it. It seems to fix the issue. Can you please confirm it?

http://koji.fedoraproject.org/koji/taskinfo?taskID=2221987
Comment 7 Jonathan Larmour 2010-06-01 14:03:23 UTC 
Thanks for looking at this. I can't see the problem any more (although I've only been able to try it manually connecting with nc rather than with a proper amanda run) so it looks ok to me.

Thanks!
Comment 8 Fedora Update System 2010-06-02 07:31:23 UTC 
xinetd-2.3.14-31.fc12 has been submitted as an update for Fedora 12.
http://admin.fedoraproject.org/updates/xinetd-2.3.14-31.fc12
Comment 9 Fedora Update System 2010-06-02 08:08:21 UTC 
xinetd-2.3.14-32.fc13 has been submitted as an update for Fedora 13.
http://admin.fedoraproject.org/updates/xinetd-2.3.14-32.fc13
Comment 10 Fedora Update System 2010-06-02 18:03:36 UTC 
xinetd-2.3.14-32.fc13 has been pushed to the Fedora 13 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update xinetd'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/xinetd-2.3.14-32.fc13
Comment 11 Fedora Update System 2010-06-02 18:03:45 UTC 
xinetd-2.3.14-31.fc12 has been pushed to the Fedora 12 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update xinetd'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/xinetd-2.3.14-31.fc12
Comment 12 Fedora Update System 2010-06-22 17:14:11 UTC 
xinetd-2.3.14-31.fc12 has been pushed to the Fedora 12 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 13 Fedora Update System 2010-06-22 17:17:56 UTC 
xinetd-2.3.14-32.fc13 has been pushed to the Fedora 13 stable repository.  If problems still persist, please make note of it in this bug report.