asynchronous connection failed in postgresql jobs

[Matt Riedemann]

The trace for the failure is here:

http://logs.openstack.org/57/105257/4/check/check-tempest-dsvm-postgres-full/f72b818/logs/tempest.txt.gz?level=TRACE#_2014-07-07_23_43_37_250

This is the console error:

2014-07-07 23:44:59.590 | tearDownClass (tempest.thirdparty.boto.test_ec2_keys.EC2KeysTest)
2014-07-07 23:44:59.590 | -----------------------------------------------------------------
2014-07-07 23:44:59.590 |
2014-07-07 23:44:59.590 | Captured traceback:
2014-07-07 23:44:59.590 | ~~~~~~~~~~~~~~~~~~~
2014-07-07 23:44:59.590 | Traceback (most recent call last):
2014-07-07 23:44:59.590 | File "tempest/thirdparty/boto/test.py", line 272, in tearDownClass
2014-07-07 23:44:59.590 | raise exceptions.TearDownException(num=fail_count)
2014-07-07 23:44:59.590 | TearDownException: 1 cleanUp operation failed

There isn't much in the n-api logs, just the 400 response.

[Matt Riedemann (mriedem)]

Failing several ec2 keypair tests here:

http://logs.openstack.org/06/103206/4/check/check-tempest-dsvm-postgres-full/b5e8f3c/console.html

[Matt Riedemann (mriedem)]

There was a new boto package uploaded to pypi on 7/1 but it seems we started seeing the keypair failures later than that.

[Matt Riedemann (mriedem)]

Given the stack traces I'm seeing here:

http://logs.openstack.org/06/103206/4/check/check-tempest-dsvm-postgres-full/b5e8f3c/logs/screen-n-api.txt.gz?level=TRACE

http://logs.openstack.org/06/103206/4/check/check-tempest-dsvm-postgres-full/b5e8f3c/logs/screen-n-cpu.txt.gz?level=TRACE

This could be a result of https://review.openstack.org/103161 somehow?

[Matt Riedemann (mriedem)]

message:"Unexpected OperationalError raised: (OperationalError) asynchronous connection failed" AND tags:"screen-n-api.txt"

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiVW5leHBlY3RlZCBPcGVyYXRpb25hbEVycm9yIHJhaXNlZDogKE9wZXJhdGlvbmFsRXJyb3IpIGFzeW5jaHJvbm91cyBjb25uZWN0aW9uIGZhaWxlZFwiIEFORCB0YWdzOlwic2NyZWVuLW4tYXBpLnR4dFwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDA0ODQwNDY0NDEzfQ==

That shows up with 14 hits but only for this cinder change, which should be unrelated I'd think:

https://review.openstack.org/#/c/103206/

[Matt Riedemann (mriedem)]

message:"Unexpected OperationalError raised: (OperationalError) asynchronous connection failed" AND tags:"screen-n-api.txt"

that shows up more now, check and gate, multiple changes, all failures.

Interestingly it only shows up in postgres jobs.

[Matt Riedemann (mriedem)]

The postgres jobs are the only ones running the nova-api-meta service so that might have something to do with this also.

[Matt Riedemann (mriedem)]

The "asynchronous connection failed" error doesn't show up before 7/8 in logstash.

[Matt Riedemann (mriedem)]

http://stackoverflow.com/questions/17514633/gevent-and-posgres-asynchronous-connection-failed

[Matt Riedemann (mriedem)]

Looks like we're running with a really old version of postgresql:

ii python-psycopg2 2.4.5-1build5 amd64 Python module for PostgreSQL

[Matt Riedemann (mriedem)]

http://logs.openstack.org/79/94679/6/check/check-tempest-dsvm-postgres-full/d2225f5/logs/postgres.txt.gz

FATAL: sorry, too many clients already

[Matt Riedemann (mriedem)]

That might be coming back to this:

https://review.openstack.org/#/c/103206/

That merged on 7/8 and that's when I first saw the concurrency issue in that patch going through the gate, (comment 4 above), now it's hitting everywhere, so that probably triggered the locks in postgresql.

[Matt Riedemann (mriedem)]

Multiple trove workers also merged on 7/8:

https://review.openstack.org/#/c/103239/

And glance api/registry workers to use number of CPUs by default merged on 7/3:

https://review.openstack.org/102665

So maybe the cinder api workers change just tipped it over.

[Matt Riedemann (mriedem)]

http://www.postgresql.org/docs/current/static/runtime-config-connection.html#GUC-MAX-CONNECTIONS

[Matt Riedemann (mriedem)]

We could try playing with max_connections, but that seems iffy.

There is also synchronous_commit=off and fsync=off which, according to the docs, provide performance benefit when you don't need to be careful about losing data, which we don't in the gate since they are throw-away VMs.

[Matt Riedemann (mriedem)]

Consensus is to try setting max_connections=200 given the default of 100 and the fact that the default for mysql is 151:

http://dev.mysql.com/doc/refman/5.5/en/too-many-connections.html

[Matt Riedemann (mriedem)]

https://review.openstack.org/#/c/105854/

[Matt Riedemann (mriedem)]

Mailing list thread on the bug:

http://lists.openstack.org/pipermail/openstack-dev/2014-July/039800.html

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/105854
Committed: https://git.openstack.org/cgit/openstack-dev/devstack/commit/?id=94c654ef37f6a0247a307578f3240f97201a3cba
Submitter: Jenkins
Branch: master

commit 94c654ef37f6a0247a307578f3240f97201a3cba
Author: Matt Riedemann <email address hidden>
Date: Wed Jul 9 12:38:36 2014 -0700

    Set postgresql max_connections=200

    Now that we have multiple workers running by default
    in various projects (nova/cinder/glance/trove), the
    postgresql job is failing intermittently with connection
    failures to the database.

    The default max_connections for postgresql is 100 so here
    we double that.

    Note that the default max_connections for mysql used to
    be 100 but is now 151, so this change brings the postgresql
    configuration more in line with mysql.

    Change-Id: I2fcae8184a82e303103795a7bf57c723e27190c9
    Closes-Bug: #1338841

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/icehouse
Review: https://review.openstack.org/121952

[OpenStack Infra (hudson-openstack)]

Change abandoned by Sean Dague (<email address hidden>) on branch: stable/icehouse
Review: https://review.openstack.org/121952