Description of problem:

beakerd crashes during startup due to EBADF when ConcurrentRotatingFileHandler tries to flock /var/log/beaker/beakerd.lock.


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

beaker-server-0.12.0-3.el6eng.noarch
python-daemon-1.6-2.el6eng.noarch
python-concurrentloghandler-0.8.4-5.el6eng.noarch


How reproducible:

Not reliably reproducible. I have only seen this in my development environment, nowhere else. It's sensitive to timing (GC sweeps are not predictable) and also depends on open file descriptors during daemonization, for example nss_ldap may cause fd numbering to work out differently and therefore this bug is not observable (or has other symptoms).


Steps to Reproduce:

1. service beakerd start


Actual results:

During beakerd startup:
Traceback (most recent call last):
  File "/usr/bin/beakerd", line 9, in <module>
    load_entry_point('bkr.server==0.12.0', 'console_scripts', 'beakerd')()
  File "/usr/lib/python2.6/site-packages/bkr/server/tools/beakerd.py", line 880, in main
    schedule()
  File "/usr/lib/python2.6/site-packages/bkr/server/tools/beakerd.py", line 753, in schedule
    log.debug("starting update_dirty_jobs thread")
  File "/usr/lib64/python2.6/logging/__init__.py", line 1044, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/usr/lib64/python2.6/logging/__init__.py", line 1173, in _log
    self.handle(record)
  File "/usr/lib64/python2.6/logging/__init__.py", line 1183, in handle
    self.callHandlers(record)
  File "/usr/lib64/python2.6/logging/__init__.py", line 1220, in callHandlers
    hdlr.handle(record)
  File "/usr/lib64/python2.6/logging/__init__.py", line 677, in handle
    self.acquire()
  File "/usr/lib/python2.6/site-packages/cloghandler.py", line 194, in acquire
    lock(self.stream_lock, LOCK_EX)
  File "/usr/lib/python2.6/site-packages/portalocker.py", line 130, in lock
    fcntl.flock(_getfd(file), flags)
IOError: [Errno 9] Bad file descriptor

Note that this stack trace is not normally observable (stderr is closed), to get it I modified beakerd.py as follows:

        d = daemon.DaemonContext(pidfile=pidfile.TimeoutPIDLockFile(pid_file, acquire_timeout=0),
                stdout=open('/tmp/beakerd.out', 'w'), stderr=open('/tmp/beakerd.err', 'w'))


Expected results:

beakerd should start normally.


Additional info:

After a *lot* of digging I eventually figured out this is a bad interaction between daemonization (done by daemon.DaemonContext.open) and the flocking in ConcurrentRotatingFileHandler.

One of the things DaemonContext does during daemonization is to close all open file descriptors. It does that by literally just looping over every possible file descriptor and calling os.close on it, ignoring EBADF. So there is an (implicit, undocumented?) assumption there that the caller has not opened any files prior to daemonization -- otherwise their file descriptor will have been just closed underneath them.

The real problem though is that, after daemonization, when we do start opening more files, the kernel assigns them file descriptor numbers which might correspond to existing (incorrectly) open file objects in Python.

In this particular case the problem is with the stream_lock file corresponding to /var/log/beaker/beakerd.lock. In beakerd code we do go to some lengths to try and ensure logs are closed before daemonization and re-opened afterwards, but the stream_lock files were being missed because (a) the ConcurrentRotatingFileHandler.close method doesn't actually close its stream_lock and (b) the handler is apparently held in a cycle somewhere so is not immediately garbage collected.

So the sequence of events is:

1. beakerd starts (before daemonization)
2. beakerd calls load_config, which configures logging which opens stream_lock files
   --> instance A of ConcurrentRotatingFileHandler has /var/log/beaker/beakerd.lock open as fd 4
3. beakerd calls purge_handlers, which attempts to close down all logging
   *BUT* there is a cycle somewhere, so instance A is still alive with fd 4 open
4. beakerd daemonizes, all fds are closed (including fd 4) even though instance A still thinks it's open
5. beakerd calls load_config again, which creates new log handlers and opens everything up again
   --> instance B of ConcurrentRotatingFileHandler has /var/log/beaker/beakerd.lock open, also as fd 4 because the kernel re-used that number
6. at some arbitrary point during startup, GC is triggered and collects the cycle containing instance A, which closes its stream_lock which closes fd 4
7. next time logging tries to use instance B, fd 4 has been closed and its stream_lock is invalid