I am trying to run our test suite using django-nose with multiple processors to cutdown on runtime. All tests pass with 1 processor, but using multiple processors produces a DatabaseError: server closed the connection unexpectedly
I found two tests that when run by themselves with multiple processors fail 90% of the time. A UserFactory is working with accounts_user and a CustomerFactory is working with accounts_customer. Note in the passing log the final UPDATE to accounts_customer is completed before the transaction is closed. In the failing log this UPDATE to accounts_customer never happens, since the transaction has already closed resulting in the DatabaseError: server closed the connection unexpectedly
I'm trying to decide what is causing the problem. I think the problem is most likely with how django or postgres is handling transacations, but it could be any of the below.
Passing postgres log:
145 (PID: 44072, TID: 0, Host: ::1(58134)) LOG: statement: SELECT * FROM "accounts_customer" INNER JOIN "accounts_user" ON ( "accounts_customer"."user_ptr_id" = "accounts_user"."id" ) WHERE "accounts_user"."email" = '[email protected]' LIMIT 21
146 (PID: 44072, TID: 0, Host: ::1(58134)) LOG: duration: 1.927 ms
147 (PID: 44072, TID: 0, Host: ::1(58134)) LOG: statement: SAVEPOINT "s140735112696576_x1"
148 (PID: 44072, TID: 0, Host: ::1(58134)) LOG: duration: 0.041 ms
149 (PID: 44072, TID: 0, Host: ::1(58134)) LOG: statement: SELECT (1) AS "a" FROM "accounts_customer" WHERE "accounts_customer"."account_number" = '87611264' LIMIT 1
150 (PID: 44072, TID: 0, Host: ::1(58134)) LOG: duration: 0.187 ms
151 (PID: 44072, TID: 0, Host: ::1(58134)) LOG: statement: INSERT INTO "accounts_user" ("password", "last_login", "email", "phone", "first_name", "last_name") VALUES ('', '2015-07-13 17:49:25.779534+00:00', '[email protected]', '', 'testJkQS', 'userUksx') RETURNING "accounts_user"."id"
152 (PID: 44072, TID: 394680, Host: ::1(58134)) LOG: duration: 0.382 ms
153 (PID: 44072, TID: 394680, Host: ::1(58134)) LOG: statement: INSERT INTO "accounts_customer" ("user_ptr_id", "advisor_id") VALUES (1, NULL)
154 (PID: 44072, TID: 394680, Host: ::1(58134)) LOG: duration: 0.199 ms
155 (PID: 44072, TID: 394680, Host: ::1(58134)) LOG: statement: RELEASE SAVEPOINT "s140735112696576_x1"
156 (PID: 44072, TID: 394680, Host: ::1(58134)) LOG: duration: 0.022 ms
157 (PID: 44072, TID: 394680, Host: ::1(58134)) LOG: statement: UPDATE "accounts_user" SET "password" = 'md5$LNepsrK4upi8$400710819735936b83344e0c47836251', "last_login" = '2015-07-13 17:49:25.779534+00:00', "is_superuser" = true, "email" = '[email protected]', "first_name" = 'testJkQS', "last_name" = 'userUksx' WHERE "accounts_user"."id" = 1
158 (PID: 44072, TID: 394680, Host: ::1(58134)) LOG: duration: 0.363 ms
****159 (PID: 44072, TID: 394680, Host: ::1(58134)) LOG: statement: UPDATE "accounts_customer" SET "advisor_id" = NULL WHERE "accounts_customer"."user_ptr_id" = 1
160 (PID: 44072, TID: 394680, Host: ::1(58134)) LOG: duration: 0.274 ms
161 (PID: 44072, TID: 0, Host: ::1(58134)) LOG: disconnection: session time: 0:00:00.156 user=rex database=test_db host=::1 port=58134
1 (PID: 44080, TID: 0, Host: ) LOG: connection received: host=::1 port=58135
Failing postgres log:
143 (PID: 43828, TID: 0, Host: ::1(58068)) LOG: statement: BEGIN
145 (PID: 43828, TID: 0, Host: ::1(58068)) LOG: statement: SELECT * FROM "accounts_customer" INNER JOIN "accounts_user" ON ( "accounts_customer"."user_ptr_id" = "accounts_user"."id" ) WHERE "accounts_user"."email" = '[email protected]' LIMIT 21
146 (PID: 43828, TID: 0, Host: ::1(58068)) LOG: duration: 1.368 ms
147 (PID: 43828, TID: 0, Host: ::1(58068)) LOG: statement: SAVEPOINT "s140735112696576_x1"
149 (PID: 43828, TID: 0, Host: ::1(58068)) LOG: statement: SELECT (1) AS "a" FROM "accounts_customer" WHERE "accounts_customer"."account_number" = '71017283' LIMIT 1
150 (PID: 43828, TID: 0, Host: ::1(58068)) LOG: duration: 0.198 ms
151 (PID: 43828, TID: 0, Host: ::1(58068)) LOG: statement: INSERT INTO "accounts_user" ("password", "last_login", "email", "phone", "first_name", "last_name",) VALUES ('', '2015-07-13 17:48:01.528782+00:00', '[email protected]', '', 'testhTiJ', 'userRxki', ) RETURNING "accounts_user"."id"
152 (PID: 43828, TID: 394672, Host: ::1(58068)) LOG: duration: 0.351 ms
153 (PID: 43828, TID: 394672, Host: ::1(58068)) LOG: statement: INSERT INTO "accounts_customer" ("user_ptr_id", "advisor_id") VALUES (1, NULL)
154 (PID: 43828, TID: 394672, Host: ::1(58068)) LOG: duration: 0.176 ms
155 (PID: 43828, TID: 394672, Host: ::1(58068)) LOG: statement: RELEASE SAVEPOINT "s140735112696576_x1"
156 (PID: 43828, TID: 394672, Host: ::1(58068)) LOG: duration: 0.033 ms
157 (PID: 43828, TID: 394672, Host: ::1(58068)) LOG: statement: UPDATE "accounts_user" SET "password" = 'md5$xN2n3doGJJHs$388f6cf97aa7ddba7c317108a7d4d511', "last_login" = '2015-07-13 17:48:01.528782+00:00', "email" = '[email protected]', "first_name" = 'testhTiJ', "last_name" = 'userRxki' WHERE "accounts_user"."id" = 1
158 (PID: 43828, TID: 394672, Host: ::1(58068)) LOG: duration: 0.291 ms
159 (PID: 43828, TID: 0, Host: ::1(58068)) LOG: disconnection: session time: 0:00:00.142 user=rex database=test_db host=::1 port=58068
1 (PID: 43833, TID: 0, Host: ) LOG: connection received: host=::1 port=58069
Stack-trace:
======================================================================
ERROR: test_my_test (website.apps.MyApp.tests.test_file.MyTestClass)
----------------------------------------------------------------------
Traceback (most recent call last):
File ".../tests/test_file.py", line 33, in test_my_test
customer1 = accounts_factories.CustomerFactory()
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/factory/base.py", line 81, in __call__
return cls.create(**kwargs)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/factory/base.py", line 559, in create
return cls._generate(True, attrs)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/factory/base.py", line 492, in _generate
cls._after_postgeneration(obj, create, results)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/factory/django.py", line 156, in _after_postgeneration
obj.save()
File "/Users/User/pkgs/MyProject/MyProject/website/apps/accounts/models.py", line 198, in save
return super(Customer, self).save(*args, **kwargs)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/models/base.py", line 589, in save
force_update=force_update, update_fields=update_fields)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/models/base.py", line 617, in save_base
updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/models/base.py", line 679, in _save_table
forced_update)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/models/base.py", line 723, in _do_update
return filtered._update(values) > 0
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/models/query.py", line 600, in _update
return query.get_compiler(self.db).execute_sql(CURSOR)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/models/sql/compiler.py", line 1005, in execute_sql
cursor = super(SQLUpdateCompiler, self).execute_sql(result_type)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/models/sql/compiler.py", line 787, in execute_sql
cursor.execute(sql, params)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/backends/utils.py", line 65, in execute
return self.cursor.execute(sql, params)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/utils.py", line 94, in __exit__
six.reraise(dj_exc_type, dj_exc_value, traceback)
File "/Users/User/pkgs/MyProject/lib/python2.7/site-packages/django/db/backends/utils.py", line 65, in execute
return self.cursor.execute(sql, params)
DatabaseError: server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
-------------------- >> begin captured logging << --------------------
factory.generate: DEBUG: BaseFactory: Preparing accounts.factories.CustomerFactory(extra={})
factory.generate: DEBUG: <class 'accounts.factories.CustomerFactory'>: Setting up next sequence (0)
factory.containers: DEBUG: LazyStub: Computing values for accounts.factories.CustomerFactory(first_name=<OrderedDeclarationWrapper for <factory.fuzzy.FuzzyText object at 0x10bf1b350>>, last_name=<OrderedDeclarationWrapper for <factory.fuzzy.FuzzyText object at 0x10bf1b390>>, email=<OrderedDeclarationWrapper for <factory.declarations.LazyAttribute object at 0x10bf1b3d0>>)
factory.generate: DEBUG: LazyAttribute: Evaluating <function <lambda> at 0x10bf1d500> on <LazyStub for accounts.factories.CustomerFactory>
factory.containers: DEBUG: LazyStub: Computed values, got accounts.factories.CustomerFactory(first_name=u'testhTiJ', last_name=u'userRxki', email='[email protected]')
factory.generate: DEBUG: BaseFactory: Generating accounts.factories.CustomerFactory(first_name=u'testhTiJ', last_name=u'userRxki', email='[email protected]')
factory.generate: DEBUG: PostGenerationMethodCall: Calling <Customer: [email protected]>.set_password('secret')
--------------------- >> end captured logging << ---------------------
Running django-nose on multiple processors doesn't work well with databases, or to be more exact, django transactions / database connectors.
Try using this package to split the tests: nose-picker. Check the last section of this tutorial on improving Django test performance.
Also, Python 3.4 includes an improved version of Sqlite3 which is supposed to be better at handling concurrency. YMMV.