Twisted Unhandled Error in Deferred - Too many open files: /var/log/

> There are also 386375 oops files.

The OOPS system is an extra moving part that doesn't really add anything. We need to get rid of it. The logs should go in MAAS' normal logs.

Now, it seems your installation has a problem so bad it's creating a crazy amount of OOPS reports and this, in turn, becomes a problem ("Too many open files"). Could you please try seeing if you could get more information about the *original* problem? I think you will be able to find more information in the OOPS files (the ones that could be written before the "Too many open files" problem started happening). OOPS files are bson encoded files in /var/log/maas/oops/<day>/; usually, `strings <oops-file>` is all it takes to get a good idea about what the problem is.

Pserv logs:

<kiko> larrymi, when was the machine upgraded to 1.7.1RC1 and what from?
<larrymi> kiko: it was upgraded from 1.7.0. We got the beta first (i think very close to time it came out) then we went to rc1 around 1st week of December timeframe.

These pserv logs are a treasure trove of OOPSes. Just in pserv.log.4.gz we have a total of :

- provisioningserver.power.poweraction.PowerActionFail: sm15k failed with return code 1: Not Found: servers/26/0 (HTTP 404)
- Failure: provisioningserver.rpc.exceptions.NodeStateViolation: The status of the node is 6; this status cannot be transitioned to a corresponding failed status.
- tftp.errors.InvalidErrorcodeError: Unknown error code: 8
- exceptions.AttributeError: 'Port' object has no attribute 'socket'
- exceptions.OSError: [Errno 17] File exists: '/var/log/maas/oops/2014-12-09'
- Failure: twisted.internet.error.ConnectionDone: Connection was closed cleanly.
  (why would that be a Failure?)
- Failure: twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion.
- provisioningserver.rpc.exceptions.NoConnectionsAvailable:
- Failure: twisted.internet.defer.CancelledError:
- Failed to login to virsh console.
- Failure: provisioningserver.rpc.exceptions.NodeStateViolation: The status of the node is 4; this status cannot be transitioned to a corresponding failed status.
- provisioningserver.power.poweraction.PowerActionFail: virsh failed with return code 1: Failed to login to virsh console.
- Failure: provisioningserver.rpc.exceptions.NodeStateViolation: The status of the node is 6; this status cannot be transitioned to a corresponding failed status.
- Failure: twisted.internet.error.TimeoutError: User timeout caused connection failure.
- exceptions.AttributeError: 'NoneType' object has no attribute 'stopListening

pserv.log.3.gz is similar, but it has a bunch more sm15k OOPSes and a large set of:

- Failure: twisted.web.error.Error: 500 INTERNAL SERVER ERROR

And pserv.log.2.gz has the actual issue reported, where we see complaints about too many open files. It starts with this:

2014-12-26 21:39:58+0000 [-] Unhandled Error
        Traceback (most recent call last):
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 423, in errback
            self._startRunCallbacks(fail)
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
            self._runCallbacks()
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1155, in gotResult
            _inlineCallbacks(r, g, deferred)
        --- <exception caught here> ---
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1097, in _inlineCallbacks
            result = result.throwExceptionIntoGenerator(g)
          File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
            return g.throw(self.type, self.value, self.tb)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/rpc/power.py", line 234, in change_power_state
            'query', context)
          File "/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 191, in _worker
            result = context.call(ctx, function, *args, **kwargs)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 118, in callWithContext
            return self.currentContext().callWithContext(ctx, func, *args, **kw)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 81, in callWithContext
            return func(*args,**kw)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/utils/twisted.py", line 148, in wrapper
            return func(*args, **kwargs)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/rpc/power.py", line 111, in perform_power_change
            return action.execute(power_change=power_change, **context)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/power/poweraction.py", line 138, in execute
            template = self.get_template()
          File "/usr/lib/python2.7/dist-packages/provisioningserver/power/poweraction.py", line 86, in get_template
            with open(self.path, "rb") as f:
        exceptions.IOError: [Errno 24] Too many open files: u'/etc/maas/templates/power/sm15k.template'

Nice that it waited for after xmas to start reporting problems.

Immediately after that, it starts to complain:

        Traceback (most recent call last):
          File "/usr/lib/python2.7/threading.py", line 783, in __bootstrap

          File "/usr/lib/python2.7/threading.py", line 810, in __bootstrap_inner

          File "/usr/lib/python2.7/threading.py", line 763, in run

        --- <exception caught here> ---
          File "/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 191, in _worker
            result = context.call(ctx, function,...

Oh, I missed an error that happens a bit before the first one in my previous comment:

        Traceback (most recent call last):
          File "/usr/lib/python2.7/dist-packages/tftp/protocol.py", line 67, in _startSession
            context, self.backend.get_reader, datagram.filename)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 118, in callWithContext
            return self.currentContext().callWithContext(ctx, func, *args, **kw)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 81, in callWithContext
            return func(*args,**kw)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/utils/twisted.py", line 62, in wrapper
            return maybeDeferred(func, *args, **kwargs)
        --- <exception caught here> ---
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 139, in maybeDeferred
            result = f(*args, **kw)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 216, in get_reader
            mac_address = get_remote_mac()
          File "/usr/lib/python2.7/dist-packages/provisioningserver/boot/__init__.py", line 106, in get_remote_mac
            return find_mac_via_arp(remote_host)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/utils/network.py", line 101, in find_mac_via_arp
            output = call_and_check(['ip', 'neigh'], env={'LC_ALL': 'C'})
          File "/usr/lib/python2.7/dist-packages/provisioningserver/utils/shell.py", line 142, in call_and_check
            process = Popen(command, *args, stdout=PIPE, stderr=PIPE, **kwargs)
          File "/usr/lib/python2.7/subprocess.py", line 710, in __init__
            errread, errwrite)
          File "/usr/lib/python2.7/subprocess.py", line 1215, in _execute_child
            errpipe_read, errpipe_write = self.pipe_cloexec()
          File "/usr/lib/python2.7/subprocess.py", line 1167, in pipe_cloexec
            r, w = os.pipe()
        exceptions.OSError: [Errno 24] Too many open files

Could we be flooding the server with find_mac_via_arp() calls?

Or just leaking descriptors? At any rate, after that error the machine is wedged and goes into an OOPS generation loop until the last one is generated:

2014-12-26 22:09:40+0000 [-] Unhandled Error
        Traceback (most recent call last):
          File "/usr/lib/python2.7/threading.py", line 783, in __bootstrap
            self.__bootstrap_inner()
          File "/usr/lib/python2.7/threading.py", line 810, in __bootstrap_inner
            self.run()
          File "/usr/lib/python2.7/threading.py", line 763, in run
            self.__target(*self.__args, **self.__kwargs)
        --- <exception caught here> ---
          File "/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 191, in _worker
            result = context.call(ctx, function, *args, **kwargs)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 118, in callWithContext
            return self.currentContext().callWithContext(ctx, func, *args, **kw)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 81, in callWithContext
            return func(*args,**kw)
          File "/usr/lib/python2.7/dist-packages/oops/publishers.py", line 38, in result
            return publisher(report)
          File "/usr/lib/python2.7/dist-packages/oops_datedir_repo/repository.py", line 133, in publish
            self.serializer.write(report, open(filename + '.tmp', 'wb'))
        exceptions.IOError: [Errno 24] Too many open files: '/var/log/maas/oops/2014-12-26/OOPS-ce59fba5782424eb6106c025b4b53192.tmp'

At which point it goes back into normality:

2014-12-26 22:10:03+0000 [-] TFTP starting on 69
2014-12-26 22:10:03+0000 [-] TFTP starting on 69
[...]

After that the only tracebacks in pserv.log.2.gz are of the sm15k issue:

2014-12-27 21:54:04+0000 [-] Unhandled Error
        Traceback (most recent call last):
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 423, in errback
            self._startRunCallbacks(fail)
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
            self._runCallbacks()
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1155, in gotResult
            _inlineCallbacks(r, g, deferred)
        --- <exception caught here> ---
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1097, in _inlineCallbacks
            result = result.throwExceptionIntoGenerator(g)
          File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 389, in throwExceptionIntoGenerator
            return g.throw(self.type, self.value, self.tb)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/rpc/power.py", line 222, in change_power_state
            power_change, context)
          File "/usr/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 191, in _worker
            result = context.call(ctx, function, *args, **kwargs)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 118, in callWithContext
            return self.currentContext().callWithContext(ctx, func, *args, **kw)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 81, in callWithContext
            return func(*args,**kw)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/utils/twisted.py", line 148, in wrapper
            return func(*args, **kwargs)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/rpc/power.py", line 111, in perform_power_change
            return action.execute(power_change=power_change, **context)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/power/poweraction.py", line 142, in execute
            return self.run_shell(rendered)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/power/poweraction.py", line 127, in run_shell
            process.returncode, shell, output))
        provisioningserver.power.poweraction.PowerActionFail: sm15k failed with return code 1:
        Not Found: servers/20/0 (HTTP 404)

(and the familiar provisioningserver.rpc.exceptions.NodeStateViolation with status 6)

Okay, and pserv.log.1.gz also has the Too many open files problem, starting with the familiar find_mac_via_arp() issue:

2015-01-03 10:07:12+0000 [-] Unhandled Error
        Traceback (most recent call last):
          File "/usr/lib/python2.7/dist-packages/tftp/protocol.py", line 67, in _startSession
            context, self.backend.get_reader, datagram.filename)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 118, in callWithContext
            return self.currentContext().callWithContext(ctx, func, *args, **kw)
          File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 81, in callWithContext
            return func(*args,**kw)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/utils/twisted.py", line 62, in wrapper
            return maybeDeferred(func, *args, **kwargs)
        --- <exception caught here> ---
          File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 139, in maybeDeferred
            result = f(*args, **kw)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/pserv_services/tftp.py", line 216, in get_reader
            mac_address = get_remote_mac()
          File "/usr/lib/python2.7/dist-packages/provisioningserver/boot/__init__.py", line 106, in get_remote_mac
            return find_mac_via_arp(remote_host)
          File "/usr/lib/python2.7/dist-packages/provisioningserver/utils/network.py", line 101, in find_mac_via_arp
            output = call_and_check(['ip', 'neigh'], env={'LC_ALL': 'C'})
          File "/usr/lib/python2.7/dist-packages/provisioningserver/utils/shell.py", line 142, in call_and_check
            process = Popen(command, *args, stdout=PIPE, stderr=PIPE, **kwargs)
          File "/usr/lib/python2.7/subprocess.py", line 710, in __init__
            errread, errwrite)
          File "/usr/lib/python2.7/subprocess.py", line 1215, in _execute_child
            errpipe_read, errpipe_write = self.pipe_cloexec()
          File "/usr/lib/python2.7/subprocess.py", line 1167, in pipe_cloexec
            r, w = os.pipe()
        exceptions.OSError: [Errno 24] Too many open files

After a few of those, a while later, we get a few other crashes caused by fd exhaustion (in check_lease_changes(), and find_ip_via_arp()) and then we go into the OOPS generation storm which lasts

until we generate the last OOPS generation traceback at 2015-01-03 12:28:08+0000.

The actual pserv.log file doesn't contain many OOPSes, and they seem to be relatively uninteresting ones with mainly two types of exception:

- twisted.internet.error.CannotListenError: Couldn't listen on 192.168.224.251:69: [Errno 98] Address already in use.
- provisioningserver.rpc.exceptions.NoConnectionsAvailable:

So my very simple-minded analysis suggests that we are doing something in MAAS which causes us to run out of FDs, possibly one of the issues for which we have a traceback above (such as the one with find_mac_via_arp() in its stack). This may be an FD leak or perhaps just the result of us trying to do too much at once, such as trying to query power status -- or something else.

As we run out of FDs we then crash in other places where new FDs are requested, finishing with the failure to generate an OOPS because that itself requires an FD, which then triggers recursive OOPS generation.

I've attached an lsof dump from the system this was happening on.

Why are there 144 open tcp connections from the cluster server to the region server?

I adjusted the ulimit on open files for our maas-clusterd to 65535 by adding this in /etc/init/maas.clusterd.conf:

ulimit -n 65535

.. right before twisted is started.

This is a count of all the unique items referred to in the lsof output.

I wonder if this lsof is from the middle of MAAS doing something (such as enlisting nodes)?

We should drop OOPS generation in 1.8; for 1.7, I'd like us to figure out if we are leaking fds and fix that if possible.

kiko, MAAS wasn't doing anything especially interesting at this point - no bulk enlistments.

> Why are there 144 open tcp connections from the cluster server to the
> region server?

I think this is lsof reporting each connection for each thread. There
appear to be only 18 distinct connections.

I've landed a change into MAAS trunk to remove all OOPS reporting. I'll mark this bug as fixed for now. Let's reopen it if we see this problem again.

A corresponding packaging change needs to be made. The change landed already - lp:~allenap/maas/oops-did-it-again - can be released in 1.7.2 and will hopefully alleviate the issue. The packaging change, which will clean-up and remove dependencies, can come with 1.8.0. The reason for this is to reduce the immediate delta and testing overhead.

Note that we still need the packaging side fixed: remove the dependency on python-oops* and the creation of the oops directory.

This bug has been reported and fixed on upstream MAAS. However, provided that the bug was listed on the debian changelog, this appears as needing verification for pending SRU [1]. This bug did not affect current MAAS in Ubuntu, hence setting this to verification-done to unblock pending SRU.

[1]:http://people.canonical.com/~ubuntu-archive/pending-sru.html