Edgewall Software
Modify

Opened 8 months ago

Closed 6 months ago

Last modified 6 months ago

#13345 closed defect (fixed)

Functional tests sometimes randomly failing

Reported by: Jun Omae Owned by: Jun Omae
Priority: normal Milestone: 1.5.3
Component: general Version: 1.5.2
Severity: normal Keywords:
Cc: Branch:
Release Notes:

Fix global shutdown crashes while creating new database connection.

API Changes:
Internal Changes:

Description

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

Attachments (0)

Change History (8)

comment:1 by Jun Omae, 7 months ago

After the following patch:

  • .travis.yml

    diff --git a/.travis.yml b/.travis.yml
    index 1a3f20cae..ffd1b9ba2 100644
    a b before_script:  
    179179script:
    180180- set -e
    181181- if [ "$build" != minimum ]; then make compile; fi
    182 - make Trac.egg-info unit-test functional-test;
     182- |
     183  make Trac.egg-info unit-test functional-test || (
     184    rc=$?
     185    for i in testenv/testing.log testenv/trac/log/trac.log \
     186             $(ls -dtr testenv/trac/log/*.html)
     187    do
     188      if [ -r "$i" ]; then
     189        echo
     190        echo "$i:"
     191        echo '========'
     192        cat "$i"
     193        echo
     194        echo '========'
     195      fi
     196    done
     197    exit $rc
     198  )
    183199before_deploy:
    184200- cat contrib/travis/edgewall_host_key >> $HOME/.ssh/known_hosts
    185201- 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

comment:2 by Jun Omae, 7 months ago

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 -

comment:3 by Jun Omae, 7 months ago

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.

comment:4 by Ryan J Ollos, 7 months ago

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

comment:5 by Jun Omae, 7 months ago

Owner: set to Jun Omae
Release Notes: modified (diff)
Status: newassigned

Committed in [17503].

in reply to:  1 comment:6 by Jun Omae, 7 months ago

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.

comment:7 by Ryan J Ollos, 6 months ago

Resolution: fixed
Status: assignedclosed

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

in reply to:  3 comment:8 by Jun Omae, 6 months ago

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.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Jun Omae.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Jun Omae to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.