"too many open files" during upgrade

Indeed, if there are 20k file handles open to Mongo something very odd is going on internally. The mgo socket pool that is meant to keep a certain number of connections open is limited to 4000 connections.

I can imagine that there are ways to create >1 pool, but we *shouldn't* inside of a single controller.

Did a quick search of the state package on the 2.2 branch. The following functions aren't closing the iterator:

state/clouds.go:

func (st *State) Clouds()

state/cloudcredentials.go

func (st *State) CloudCredentials(user names.UserTag, cloudName string)

state/lease/client.go

func (client *client) readEntries // doesn't close iterator if leaseDoc.entry() returns an error

state/prune.go

The deleteInBatches function doesn't close the iterator, nor do either of the call sites.

state/upgrades.go

func updateLegacyLXDCredentialsOps(...)
func UpgradeNoProxyDefaults(st *State) error
func RemoveNilValueApplicationSettings(st *State) error

I'm guessing, quite wildly I must add, that during the upgrade process, we get the credentails for every model for potential model upgrades.

However, all of these are worrying and will cause problems.

The pruner also not closing the iterator will leak over time causing lost file handles.

https://github.com/juju/juju/pull/8255

Unfortunately this also happened with 2.2.9, so it wasn't the iterators, but is something else.

For the file handle issues, digging through the log file from bug #1742604

The controller was happily started here:
2018-01-11 02:25:53 INFO juju.cmd supercommand.go:63 running jujud [2.2.9 gc go1.8]

Things generally seem happy, with model workers coming up and connecting correctly.

Up until we get to here:

2018-01-11 02:26:13 INFO juju.apiserver.common password.go:105 setting password for "machine-1"
2018-01-11 02:26:19 INFO juju.apiserver.connection request_notifier.go:80 agent login: machine-1 for dd562d7d-512e-4241-83a1-3a64cd84439b
2018-01-11 02:26:20 WARNING juju.mongo open.go:165 TLS handshake failed: read tcp 10.25.2.111:46598->10.25.2.109:37017: read: connection reset by peer
2018-01-11 02:26:20 WARNING juju.mongo open.go:165 TLS handshake failed: read tcp 10.25.2.111:46592->10.25.2.109:37017: read: connection reset by peer
2018-01-11 02:26:20 INFO juju.state.pool.txnwatcher txnwatcher.go:135 watcher loop failed: watcher iteration error: Closed explicitly

The TXN watcher suddenly gets a tcp read failure trying to read from mongo, and that causes its connection to get reset, and flagged as "Closed explicitly".

Now, I don't know if that is mongo closing the connection, something we did on our end, or something else.

But after that, we get a *flurry* of:
2018-01-11 02:26:20 INFO juju.worker runner.go:483 stopped "txnlog", err: Closed explicitly
2018-01-11 02:26:20 ERROR juju.worker runner.go:392 exited "txnlog": Closed explicitly
2018-01-11 02:26:20 INFO juju.worker runner.go:467 restarting "txnlog" in 1s
2018-01-11 02:26:20 INFO juju.worker runner.go:483 stopped "leadership", err: Closed explicitly
2018-01-11 02:26:20 ERROR juju.worker runner.go:392 exited "leadership": Closed explicitly
2018-01-11 02:26:20 INFO juju.worker runner.go:467 restarting "leadership" in 1s
2018-01-11 02:26:20 INFO juju.worker runner.go:483 stopped "leadership", err: Closed explicitly
2018-01-11 02:26:20 ERROR juju.worker runner.go:392 exited "leadership": Closed explicitly
2018-01-11 02:26:20 INFO juju.worker runner.go:467 restarting "leadership" in 1s
2018-01-11 02:26:20 INFO juju.state.presence presence.go:186 watcher loop failed: Closed explicitly
2018-01-11 02:26:20 INFO juju.worker runner.go:483 stopped "presence", err: Closed explicitly
2018-01-11 02:26:20 ERROR juju.worker runner.go:392 exited "presence": Closed explicitly
2018-01-11 02:26:20 INFO juju.worker runner.go:467 restarting "presence" in 1s

Which then proceeds onward until we get to:
2018-01-11 02:26:21 INFO juju.worker runner.go:477 start "txnlog"
2018-01-11 02:26:24 WARNING juju.mongo open.go:165 TLS handshake failed: read tcp 10.25.2.111:38931->10.25.2.109:37017: read: connection reset by peer
2018-01-11 02:26:24 WARNING juju.mongo open.go:165 TLS handshake failed: read tcp 10.25.2.111:38909->10.25.2.109:37017: read: connection reset by peer
...
and
2018-01-11 02:26:25 WARNING juju.mongo open.go:159 mongodb connection failed, will retry: dial tcp 10.25.2.109:37017: i/o timeout
2018-01-11 02:26:25 WARNING juju.mongo open.go:159 mongodb connection failed, will retry: dial tcp 10.25.2.109:37017: i/o timeout
2018-01-11 02:26:25 WARNING juju.mongo open.go:159 mongodb connection failed...

As a summary comment, my first guess is that if we get an error during TLS negotation, we are failing to close the underlying socket.

Looking at the code to dial Mongo, I think it is correct:
  c, err := net.DialTimeout("tcp", addr, opts.Timeout)
  if err != nil {
   logger.Warningf("mongodb connection failed, will retry: %v", err)
   return nil, err
  }
  if tlsConfig != nil {
   cc := tls.Client(c, tlsConfig)
   if err := cc.Handshake(); err != nil {
    logger.Warningf("TLS handshake failed: %v", err)
    if err := c.Close(); err != nil {
     logger.Warningf("failed to close connection: %v", err)
    }
    return nil, err
   }
   c = cc
  }

The only question is if DialTimeout returns an error, would you ever need to close the connection? I would assume that 'c' is nil at that point.
And the error we're seeing in the log file is:
2018-01-11 02:26:20 WARNING juju.mongo open.go:165 TLS handshake failed: read tcp 10.25.2.111:46598->10.25.2.109:37017: read: connection reset by peer

"handshake failed"

looks like it should be closing the file handle correctly.

The other error that we are seeing, though, is "TLS handshake error" coming from the http package. Which is more the API server layer, than the Mongo layer.

I haven't tracked down where those are actually coming from. What is really weird is that it is saying it is happening in "log.go line 168", but we don't have a 'log.go' file in the Juju code base.

I do see several places that are creating an "apiserver" logger:
./juju/apiserver/apiserver.go:48:var logger = loggo.GetLogger("juju.apiserver")
./juju/cmd/jujud/agent/machine.go:1509: logger := loggo.GetLogger("juju.apiserver")

And the issue with the latter one is that it is part of the observer factories, thus is likely to be passed to something else.

I haven't found any obvious log.go files that are using a logger object on line 168.

We haven't heard of this problem for a while, it is possible that it has been fixed inadvertantly.

Seeing this with a 2.3.8 to 2.4.3 upgrade: https://pastebin.canonical.com/p/nDJsp6gt66/

Marking as Won't Fix for 2.3 and 2.4 series since we are not planning to make any further releases in these series at this stage.

This bug has not been updated in 2 years, so we're marking it Low importance. If you believe this is incorrect, please update the importance.