Functional tests sometimes randomly failing

[Jun Omae]

We recently encountered random failures of functional tests on Travis CI. Probably, Proxy.get_source() in better_twill.py has something wrong, e.g race condition.

I'd like to fix the issue before release of 1.6 because it leads stopping release procedure when release tagging.

======================================================================
ERROR: runTest (trac.wiki.tests.functional.TestWikiDelete)
Delete a wiki page.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/travis/build/edgewall/trac/trac/wiki/tests/functional.py", line 51, in runTest
    tc.find("Are you sure you want to completely delete this page?")
  File "/home/travis/build/edgewall/trac/trac/tests/functional/better_twill.py", line 191, in find
    raise AssertionError("Regex didn't match: {!r} not found in {}"
AssertionError: Regex didn't match: 'Are you sure you want to completely delete this page?' not found in file:///home/travis/build/edgewall/trac/testenv/trac/log/TestWikiDelete.html

======================================================================
ERROR: runTest (trac.ticket.tests.functional.admin.TestAdminMilestoneDetail)
Admin modify milestone details
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/travis/build/edgewall/trac/trac/ticket/tests/functional/admin.py", line 298, in runTest
    self._tester.login('user')
  File "/home/travis/build/edgewall/trac/trac/tests/functional/tester.py", line 50, in login
    tc.find("Login")
  File "/home/travis/build/edgewall/trac/trac/tests/functional/better_twill.py", line 191, in find
    raise AssertionError("Regex didn't match: {!r} not found in {}"
AssertionError: Regex didn't match: 'Login' not found in file:///home/travis/build/edgewall/trac/testenv/trac/log/TestAdminMilestoneDetail.html

[Jun Omae]

After the following patch:

.travis.yml

@@ -179 +179 @@
 script:
 - set -e
 - if [ "$build" != minimum ]; then make compile; fi
-- make Trac.egg-info unit-test functional-test;
+- |
+  make Trac.egg-info unit-test functional-test || (
+    rc=$?
+    for i in testenv/testing.log testenv/trac/log/trac.log \
+             $(ls -dtr testenv/trac/log/*.html)
+    do
+      if [ -r "$i" ]; then
+        echo
+        echo "$i:"
+        echo '========'
+        cat "$i"
+        echo
+        echo '========'
+      fi
+    done
+    exit $rc
+  )
 before_deploy:
 - cat contrib/travis/edgewall_host_key >> $HOME/.ssh/known_hosts
 - keyfile=/tmp/id_rsa

I found Internal Server Error in ​https://travis-ci.com/github/jun66j5/trac/jobs/486161318, however the AttributeError is not logged in testenv/testing.log nor testenv/trac/log/trac.log.

testenv/trac/log/TestAdminMilestoneDetail.html:
========
Internal Server Error

TracError: AttributeError: 'tuple' object has no attribute 'close'
========

I noticed another issue, AssertionError: This pool has already been destroyed. I guess the issue raises on Trac 1.0 - 1.4 with Python 2 also.

127.0.0.1 - - [25/Feb/2021 10:48:08] "GET /admin/versioncontrol/repository/t11618 HTTP/1.1" 200 -
Exception ignored in: <function SubversionRepository.__del__ at 0x7f2bcbe18ca0>
Traceback (most recent call last):
  File "/home/travis/build/jun66j5/trac/tracopt/versioncontrol/svn/svn_fs.py", line 412, in __del__
    self.close()
  File "/home/travis/build/jun66j5/trac/tracopt/versioncontrol/svn/svn_fs.py", line 455, in close
    self.pool.destroy()
  File "/home/travis/build/jun66j5/trac/tracopt/versioncontrol/svn/svn_fs.py", line 211, in destroy
    self.apr_pool_destroy(self._pool)
  File "/home/travis/virtualenv/python3.9.1/lib/python3.9/site-packages/svn/core.py", line 300, in svn_pool_destroy
    pool.destroy()
  File "/home/travis/virtualenv/python3.9.1/lib/python3.9/site-packages/libsvn/core.py", line 9440, in destroy
    self.assert_valid()
  File "/home/travis/virtualenv/python3.9.1/lib/python3.9/site-packages/libsvn/core.py", line 9426, in assert_valid
    assert self.valid(), "This pool has already been destroyed"
AssertionError: This pool has already been destroyed
Exception ignored in: <function Pool.__del__ at 0x7f2bcbe185e0>
Traceback (most recent call last):
  File "/home/travis/build/jun66j5/trac/tracopt/versioncontrol/svn/svn_fs.py", line 222, in __del__
    self.destroy()
  File "/home/travis/build/jun66j5/trac/tracopt/versioncontrol/svn/svn_fs.py", line 211, in destroy
    self.apr_pool_destroy(self._pool)
  File "/home/travis/virtualenv/python3.9.1/lib/python3.9/site-packages/svn/core.py", line 300, in svn_pool_destroy
    pool.destroy()
  File "/home/travis/virtualenv/python3.9.1/lib/python3.9/site-packages/libsvn/core.py", line 9440, in destroy
    self.assert_valid()
  File "/home/travis/virtualenv/python3.9.1/lib/python3.9/site-packages/libsvn/core.py", line 9426, in assert_valid
    assert self.valid(), "This pool has already been destroyed"
AssertionError: This pool has already been destroyed

[Jun Omae]

Applying jomae.git@trunk:t13345, I get the following traceback in testenv/testing.log at ​https://travis-ci.com/github/jun66j5/trac/jobs/486246637. The db pool with PostgreSQL has something wrong.

127.0.0.1 - - [25/Feb/2021 16:06:33] "GET /milestone/SuckingSequential HTTP/1.1" 200 -
Traceback (most recent call last):
  File "/home/travis/build/jun66j5/trac/trac/web/main.py", line 573, in dispatch_request
    env = open_environment(env_path, use_cache=not run_once)
  File "/home/travis/build/jun66j5/trac/trac/env.py", line 857, in open_environment
    env.shutdown()
  File "/home/travis/build/jun66j5/trac/trac/env.py", line 506, in shutdown
    DatabaseManager(self).shutdown(tid)
  File "/home/travis/build/jun66j5/trac/trac/db/api.py", line 551, in shutdown
    self._cnx_pool.shutdown(tid)
  File "/home/travis/build/jun66j5/trac/trac/db/pool.py", line 218, in shutdown
    _backend.shutdown(tid)
  File "/home/travis/build/jun66j5/trac/trac/db/pool.py", line 195, in shutdown
    db.close()
AttributeError: 'tuple' object has no attribute 'close'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/travis/build/jun66j5/trac/trac/web/main.py", line 605, in dispatch_request
    raise HTTPInternalServerError(env_error) from env_error
127.0.0.1 - - [25/Feb/2021 16:06:33] "GET /milestone/ChicleStylizes HTTP/1.1" 200 -
abc.HTTPInternalServerError: 500 Internal Server Error ('tuple' object has no attribute 'close')
127.0.0.1 - - [25/Feb/2021 16:06:33] "GET / HTTP/1.1" 500 -

[Jun Omae]

Proposed changes in [086f3f21b/jomae.git].

The issue occurs when ConnectionPoolBackend.shutdown(None) is invoked while calling ConnectionPoolBackend.get_cnx(). The situation can occur because tracd is multi-thread server and webdriver uses multiple requests.

1. The .get_cnx() temporarily sets a tuple (e.g. ('create', None)) to ._active[(tid, key)] as deferred marker to reduce the time of locking _active property.
2. After releasing the lock, it tries to connect database.
3. While locking _active property, replace deferred marker in _active[] with real connection.

All of stable branches also have this issue.

I think ideally ConnectionPoolBackend.shutdown(None) invoked by changes of trac.ini should do after termination of current requests.

[Ryan J Ollos]

I can create the 1.5.3 release this weekend if the changes are pushed.

[Jun Omae]

Committed in [17503].

[Jun Omae]

I noticed another issue, AssertionError: This pool has already been destroyed. I guess the issue raises on Trac 1.0 - 1.4 with Python 2 also.

I've filed in #13356.

[Ryan J Ollos]

Looks like this is resolved so I'll close it.

[Jun Omae]

I think ideally ConnectionPoolBackend.shutdown(None) invoked by changes of trac.ini should do after termination of current requests.

At least, multitherading web server with SQLite crashes due to the behavior.

I've filed in #13390.