Bug 842039

Summary: denyhosts fails to start using systemctl when /var/log/secure is large
Product: [Fedora] Fedora Reporter: Matt Hirsch <matthew.hirsch>
Component: denyhostsAssignee: Jason Tibbitts <j>
Status: CLOSED WONTFIX QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 17CC: dennis, j
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-08-01 12:33:13 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 Matt Hirsch 2012-07-21 06:37:42 UTC
Description of problem:
I installed denyhosts in Fedora 17 using yum. Using the default configuration (I haven't changed anything after installing the package) I cannot start the denyhosts service using systemctl. I get the message "Job failed. See system journal and 'systemctl status' for details."


Version-Release number of selected component (if applicable):
denyhosts-2.6-26.fc17.noarch

How reproducible:
always - with large /var/log/secure file

Steps to Reproduce:
1. install denyhosts (use default configuration)
2. #systemctl start denyhosts.service
  
Actual results:
"Job failed. See system journal and 'systemctl status' for details."

Expected results:
Running denyhosts script

Additional info:

The details from "systemctl status denyhosts.service" are:

# systemctl status denyhosts.service
denyhosts.service - SSH log watcher
	  Loaded: loaded (/usr/lib/systemd/system/denyhosts.service; disabled)
	  Active: failed (Result: timeout) since Sat, 21 Jul 2012 02:19:04 -0400; 9s ago
	 Process: 25371 ExecStart=/usr/bin/denyhosts.py --daemon --config=/etc/denyhosts.conf (code=killed, signal=TERM)
	 Process: 25368 ExecStartPre=/bin/rm -f /run/lock/subsys/denyhosts (code=exited, status=0/SUCCESS)
	  CGroup: name=systemd:/system/denyhosts.service

In /var/log/messages:

Jul 21 02:23:33 <hostname> systemd[1]: denyhosts.service operation timed out. Terminating.
Jul 21 02:23:33 <hostname> systemd[1]: Unit denyhosts.service entered failed state.

If I run the command listed in the systemctl status message as root, it hangs on the terminal taking 100% CPU. Running strace on the pid of denyhosts.py, this line is repeated again and again:

stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0

Hitting Control-C, I get the following python backtrace:


^CTraceback (most recent call last):
  File "/usr/bin/denyhosts.py", line 170, in <module>
    first_time, noemail, daemon)
  File "/usr/lib/python2.7/site-packages/DenyHosts/deny_hosts.py", line 82, in __init__
    offset = self.process_log(logfile, last_offset)
  File "/usr/lib/python2.7/site-packages/DenyHosts/deny_hosts.py", line 423, in process_log
    login_attempt.add(user, host, success, invalid)
  File "/usr/lib/python2.7/site-packages/DenyHosts/loginattempt.py", line 93, in add
    self.__age_reset_invalid)
  File "/usr/lib/python2.7/site-packages/DenyHosts/loginattempt.py", line 123, in increment_count
    count_inst[key].age_count(age_reset)
  File "/usr/lib/python2.7/site-packages/DenyHosts/counter.py", line 37, in age_count
    epoch = time.mktime(time.strptime(self.__date))
  File "/usr/lib64/python2.7/_strptime.py", line 454, in _strptime_time
    return _strptime(data_string, format)[0]
  File "/usr/lib64/python2.7/_strptime.py", line 321, in _strptime
    _regex_cache[format] = format_regex
KeyboardInterrupt


I found that my /var/log/secure file is 296M, mostly filled with bogus login attempts (I really need denyhosts, apparently). If I temporarily move /var/log/secure away, replacing it with an empty file, denyhosts starts correctly.

Comment 1 Jason Tibbitts 2012-08-12 16:51:21 UTC
Your situation is definitely atypical; even for a large file (and that's not really large).  You're welcome to increase the systemd job timeout (with TimeoutStartSec=), or start it manually and allow it to process the file.  I don't think either the strace info or the backtrace you posted shows anything particularly interesting or problematic, just that it's working through the log processing entries.  Otherwise there's not much here for me to go on; you just say it "hangs" but you don't say how long you let it run.  Try letting it run for, well, however long it takes.  Or just rotate out your secure file and start from scratch.  The stale entries are rarely all that useful.

If is, of course, possible that there's something in your secure file that actually confuses denyhosts.  If so, perhaps some kind of bisection would help to find it, but unless you can give me the exact bits of that 296MB file cause the problem, there's not much I can do.

I'll document the fact that initial startups can take a while with a large /var/log/secure file and suggest running it to completion manually before starting the service, but that's about all I think I'm willing to do in this case since regular startup should definitely complete before the default 90 second systemd timeout or else something really is wrong.

Comment 2 Matt Hirsch 2012-08-12 20:42:52 UTC
Jason, thanks for your comments. I ended up letting denyhosts run on the terminal overnight, and it did successfully complete.

I think documenting this behavior is a good start. But it seems to me that if denyhosts is launched with the --daemon switch, it should fork away before starting this potentially long process of indexing the secure file. I think its ok for the service to not start immediately when invoked for the first time, but its less good to have it fail to start altogether.

Comment 3 Jason Tibbitts 2012-08-12 21:42:11 UTC
You can argue that, but it's entirely a matter for upstream and not something I'm going to fix for Fedora.  And upstream is unlikely to rearchitect their software to change this in the foreseeable future, so I can either keep open a bug I cannot fix or document the intended behavior.  I could also just turn off systemd's timeout detection for this package, which I think is far less useful.

In practice this doesn't happen except in very degenerate cases anyway, so I'm really not concerned.

Comment 4 Fedora End Of Life 2013-07-04 04:03:19 UTC
This message is a reminder that Fedora 17 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 17. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '17'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 17's end of life.

Bug Reporter:  Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 17 is end of life. If you 
would still like  to see this bug fixed and are able to reproduce it 
against a later version  of Fedora, you are encouraged  change the 
'version' to a later Fedora version prior to Fedora 17's end of life.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 5 Fedora End Of Life 2013-08-01 12:33:16 UTC
Fedora 17 changed to end-of-life (EOL) status on 2013-07-30. Fedora 17 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.