Log a warning when interpreter optimization level is nonzero

[Ryan J Ollos]

Documented in #8956 and recently raised in ​gmessage:trac-users:AQpVWTXVwsg/Rkey-2SHFQAJ, the header and footer are non displayed when Python interpreter optimizations are enabled.

The issue can be reproduced with TracStandalone using the PYTHONOPTIMIZE environment variable.

$PYTHONOPTIMIZE=1 tracd -r -s -p 8000 proj-1.0

The optimization level can be retrieved at runtime, so we could log a warning, raise an error or display the optimization level in the System Information on the About Trac page.

$python -OO
Python 2.7.11 (default, Dec  5 2015, 14:44:53) 
[GCC 4.2.1 Compatible Apple LLVM 7.0.0 (clang-700.1.76)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import sys
>>> sys.flags.optimize
2
$python
Python 2.7.11 (default, Dec  5 2015, 14:44:53) 
[GCC 4.2.1 Compatible Apple LLVM 7.0.0 (clang-700.1.76)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import sys
>>> sys.flags.optimize
0

[Ryan J Ollos]

I'm unsure of the best location to do this check. Here is a proposed patch, which puts the check next to warn_setuptools_issue:

trac/web/main.py

@@ -391 +391 @@
         return resp
 
 
-_warn_setuptools = False
+_initialization_checks = False
 _slashes_re = re.compile(r'/+')
 
 def dispatch_request(environ, start_response):
@@ -401 +401 @@
     :param start_response: the WSGI callback for starting the response
     """
 
-    global _warn_setuptools
-    if _warn_setuptools is False:
-        _warn_setuptools = True
+    global _initialization_checks
+    if _initialization_checks is False:
         warn_setuptools_issue(out=environ.get('wsgi.errors'))
 
+        if sys.flags.optimize != 0:
+            raise EnvironmentError("Python with optimizations enabled is not "
+                                   "supported.")
+        _initialization_checks = True
+
     # SCRIPT_URL is an Apache var containing the URL before URL rewriting
     # has been applied, so we can use it to reconstruct logical SCRIPT_NAME
     script_url = environ.get('SCRIPT_URL')

The EnvironmentError is used because it's also used here: tags/trac-1.0.10/trac/web/main.py@:486-490#L441​. However, this results in an empty response.

Another idea is to raise an exception in the Environment initializer.

[Ryan J Ollos]

Replying to Ryan J Ollos:

Another idea is to raise an exception in the Environment initializer.

I'm tending to favor this approach because I think the error message will be more clear.

[Jun Omae]

Raising an EnvironmentError sounds good. I consider we should check sys.flags.optimize every time rather than first time. If checking only first time, it might be ignored. Also, it would be good to add the same check to run() in trac/admin/console.py.

[Ryan J Ollos]

Replying to Jun Omae:

Also, it would be good to add the same check to run() in trac/admin/console.py.

Do you think we should raise an error there too, or just log a warning to the console?

[Jun Omae]

Also, it would be good to add the same check to run() in trac/admin/console.py.

Do you think we should raise an error there too, or just log a warning to the console?

I think trac-admin should raise an error and stop, if trac-admin doesn't work with non-zero optimization level. However, it seems trac-admin $ENV initenv at least works well with non-zero optimization level.

[Ryan J Ollos]

Replying to Jun Omae:

I think trac-admin should raise an error and stop, if trac-admin doesn't work with non-zero optimization level. However, it seems trac-admin $ENV initenv at least works well with non-zero optimization level.

I was thinking similarly. As far as I know the only problem seen with non-zero optimization level is when rendering templates. The result is missing content on the page, and it may just be a Genshi issue that will go away when we switch to Jinja2.

[Christian Boos]

Replying to Ryan J Ollos:

… and it may just be a Genshi issue that will go away when we switch to Jinja2.

JFYI, I run the tests on the Jinja2 branch and got 3 unit-tests failing:

======================================================================
ERROR: test_invalid_argument_raises (trac.tests.core.ComponentTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "d:\Trac\repos\trunk\trac\tests\core.py", line 363, in test_invalid_argument_raises
    self.assertRaises(AssertionError, Component)
  File "C:\Dev\Miniconda2-x64\lib\unittest\case.py", line 473, in assertRaises
    callableObj(*args, **kwargs)
  File "d:\Trac\repos\trunk\trac\core.py", line 134, in __call__
    compmgr = args[0]
IndexError: tuple index out of range

======================================================================
ERROR: test_invalid_nesting (trac.db.tests.api.WithTransactionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "d:\Trac\repos\trunk\trac\db\tests\api.py", line 213, in test_invalid_nesting
    @with_transaction(env)
  File "d:\Trac\repos\trunk\trac\db\api.py", line 97, in transaction_wrapper
    fn(ldb)
  File "d:\Trac\repos\trunk\trac\db\tests\api.py", line 215, in level0
    @with_transaction(env, Connection())
  File "d:\Trac\repos\trunk\trac\db\api.py", line 91, in transaction_wrapper
    fn(db)
  File "d:\Trac\repos\trunk\trac\db\tests\api.py", line 217, in level1
    raise Error()
Error

======================================================================
FAIL: test_implements_called_outside_classdef (trac.tests.core.ComponentTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "d:\Trac\repos\trunk\trac\tests\core.py", line 154, in test_implements_called_outside_classdef
    self.fail('Expected AssertionError')
AssertionError: Expected AssertionError

----------------------------------------------------------------------

Actually, you'd get the same on trunk (see r14624).

[Ryan J Ollos]

Proposed changes in log:rjollos.git:t12352_warn_python_optimizations.

I noticed that return code was not being set in the shell. After [d9dd962b/rjollos.git], the return code is set.

$PYTHONOPTIMIZE=2 trac-admin help
Python with optimizations is not supported.
$echo $?
2

[Ryan J Ollos]

Replying to Jun Omae:

Raising an EnvironmentError sounds good. I consider we should check sys.flags.optimize every time rather than first time. If checking only first time, it might be ignored.

It appears it's not possible to change the Python optimization level without restarting the Python process and recompiling the byte code, so I'm not sure that it's really necessary to check sys.flags.optimize on every request. However, the changes I've proposed implement a check of sys.flags.optimize on every request in case there is something I've overlooked.

[Jun Omae]

The sys.flags is available since Python 2.6.

  File "/run/shm/0288adadc5aaed1f038d03fb7d89997b748675ec/py25-sqlite/trac/admin/console.py", line 575, in _run
    if sys.flags.optimize != 0:
AttributeError: 'module' object has no attribute 'flags'

[Ryan J Ollos]

I guess we can just apply the change to 1.2dev then. The issue is rather rare anyway.

[Ryan J Ollos]

Replying to Ryan J Ollos:

I noticed that return code was not being set in the shell. After [d9dd962b/rjollos.git], the return code is set.

$PYTHONOPTIMIZE=2 trac-admin help
Python with optimizations is not supported.
$echo $?
2

See comment:27:ticket:6998.

[Ryan J Ollos]

Replying to Jun Omae:

I consider we should check sys.flags.optimize every time rather than first time. If checking only first time, it might be ignored.

That makes sense. I misunderstood the issue when discussing in comment:11, and didn't see the issue previously because I was running tracd with -r.

[Ryan J Ollos]

Fixed on trunk in [14688].

[Jun Omae]

Tests failing on AppVeyor CI, ​https://ci.appveyor.com/project/edgewall-org/trac/build/trunk.174/job/ai70ynepcidgde1s. It seems newline on Windows leads the failure.

[Ryan J Ollos]

Fixed in [14699].

[Ryan J Ollos]

Refactoring in r15053, merged to trunk in r15054.

[Ryan J Ollos]

Oddly, I get a test failure when Babel is not installed:

FAIL: test_python_with_optimizations_returns_error (trac.admin.tests.console.TracadminTestCase)
Error is returned when a command is executed in interpreter
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rjollos/Documents/Workspace/trac-dev/teo-rjollos.git/trac/admin/tests/console.py", line 221, in test_python_with_optimizations_returns_error
    self.assertEqual(2, proc.returncode)
  File "/Users/rjollos/Documents/Workspace/trac-dev/teo-rjollos.git/trac/admin/tests/console.py", line 155, in assertEqual
    output, msg)
AssertionError: 2 != 1

I can reproduce from the command line:

$ python -O -m trac.admin.console
Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/runpy.py", line 174, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "/usr/local/Cellar/python/2.7.13/Frameworks/Python.framework/Versions/2.7/lib/python2.7/runpy.py", line 72, in _run_code
    exec code in run_globals
  File "/Users/rjollos/Documents/Workspace/trac-dev/teo-rjollos.git/trac/admin/console.py", line 651, in <module>
    sys.exit(run())
  File "/Users/rjollos/Documents/Workspace/trac-dev/teo-rjollos.git/trac/admin/console.py", line 642, in run
    translation.activate(get_console_locale())
  File "trac/admin/api.py", line 226, in get_console_locale
    return get_negotiated_locale(locales)
  File "trac/util/translation.py", line 360, in get_negotiated_locale
    normalize(available_locales))
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve/lib/python2.7/site-packages/babel/core.py", line 218, in negotiate
    SVN_ERR_FS_NO_SUCH_STRING = _core.SVN_ERR_FS_NO_SUCH_STRING
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve/lib/python2.7/site-packages/babel/core.py", line 287, in parse
    SVN_ERR_RA_OUT_OF_DATE = _core.SVN_ERR_RA_OUT_OF_DATE
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve/lib/python2.7/site-packages/babel/core.py", line 272, in _try_load
    SVN_ERR_REPOS_LOCKED = _core.SVN_ERR_REPOS_LOCKED
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve/lib/python2.7/site-packages/babel/core.py", line 166, in __init__
    SVN_ERR_WC_UNWIND_MISMATCH = _core.SVN_ERR_WC_UNWIND_MISMATCH
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve/lib/python2.7/site-packages/babel/localedata.py", line 50, in exists
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve/lib/python2.7/site-packages/babel/localedata.py", line 35, in normalize_locale
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve/lib/python2.7/site-packages/babel/localedata.py", line 62, in locale_identifiers
OSError: [Errno 2] No such file or directory: '/Users/rjollos/Documents/Workspace/trac-dev/pve/lib/python2.7/site-packages/babel/locale-data'

It seems an ImportError is not raised when using -O:

$ python -O -c "from babel import Locale"
$ python -c "from babel import Locale"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
ImportError: No module named babel

[Ryan J Ollos]

It seems there was a babel directory in site-packages, even though Babel was uninstalled using pip:

$ ls ../pve/lib/python2.7/site-packages/babel
__init__.pyo    dates.pyo       numbers.pyo     util.pyo
_compat.pyo     localedata.pyo  plural.pyo
core.pyo        localtime       support.pyo

After deleting that directory there is no test failure.

[Ryan J Ollos]

It's a defect with pip, that the .pyo files are not uninstalled. The issue is ​claimed to be fixed, but does not seem to be fixed in pip 10.0.0dev.

Here's the behavior with pip 9.0.1 (same behavior with 10.0.0dev):

$ pip install requests
Collecting requests
  Using cached requests-2.14.1-py2.py3-none-any.whl
Installing collected packages: requests
Successfully installed requests-2.14.1
$ python -O -c "import requests"
$ pip uninstall requests
Uninstalling requests-2.14.1:
[...]
$ ls pve/lib/python2.7/site-packages/requests/
__init__.pyo            exceptions.pyo
_internal_utils.pyo     hooks.pyo
adapters.pyo            models.pyo
api.pyo                 packages
auth.pyo                sessions.pyo
certs.pyo               status_codes.pyo
compat.pyo              structures.pyo
cookies.pyo             utils.pyo

[Ryan J Ollos]

​Reported the issue for pip.

[Ryan J Ollos]

Replying to Ryan J Ollos:

​Reported the issue for pip.

The issue has been ​fixed on master and should be included in the next pip release (10.0.2 or 10.1, I would guess).

[Ryan J Ollos]

Edited 1.3/TracModWSGI@2 to account for switch to Jinja2.

Also, edited WikiMacros@54 since running with optimizations is no longer allowed. However, macro documentation is no longer removed when running with -OO optimizations with introduction of cleandoc_ in r10617, so the issue would only be present for a plugin that doesn't use cleandoc_.

I don't see any reason to raise an error when running with Python optimizations on trunk. Proposed changes in [2c8f2cd28/rjollos.git]. Edits to 1.3/TracModWSGI and 1.3/TracModPython would also be needed.

[Jun Omae]

Replying to Ryan J Ollos:

I don't see any reason to raise an error when running with Python optimizations on trunk. Proposed changes in [2c8f2cd28/rjollos.git]. Edits to 1.3/TracModWSGI and 1.3/TracModPython would also be needed.

I tested the proposed changes. Removing the check looks good to me.

[Ryan J Ollos]

Thanks for the review. Reverted r14688, r14699 and r15053 on trunk in r16697.

Edited 1.3/TracModPython@2.