Trap NotImplementedError

[Ryan J Ollos]

Raising a NotImplementedError exception results in the following page:

Note that this standard error screen suggests that the user might create a ticket. If the developer is explicitly raising a NotImpementedError, we probably don't want users reporting these issues (#11611). Ideally the NotImplementedError would have an explanation, perhaps even a link to the ticket in which the feature/method will be implemented. That may be applicable to the scenario that led to the screen capture.

Traceback (most recent call last):
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/web/main.py", line 554, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/web/main.py", line 247, in dispatch
    resp = chosen_handler.process_request(req)
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/versioncontrol/web_ui/log.py", line 271, in process_request
    for cpath, kind, chg, bpath, brev in changeset.get_changes():
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/versioncontrol/api.py", line 1244, in get_changes
    raise NotImplementedError
NotImplementedError: 

We could add a TracNotImplementedError:

class TracNotImplementedError(TracError, NotImplementedError):

Or we could trap NotImplementedError where TracError is trapped.

[Ryan J Ollos]

Proposed changes in log:rjollos.git:t12385_trap_not_implemented. I think [12cdd650/rjollos.git] could be adapted and applied to 1.0-stable.

I wanted to test with MercurialPlugin but haven't managed to install due to issue noted in comment:26:ticket:7346.

[Jun Omae]

Functional tests has 2 failures. How about simply raising a TracError instead of NotImplementedError?

python trac/tests/functional/__init__.py 
..F.........F............................................................................................................................................................................................................
======================================================================
FAIL: runTest (trac.tests.functional.testcases.TestErrorPage)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/run/shm/12cdd65075279a8db3acc4d920ed8fd0b3a2cbb1/py27-sqlite/trac/tests/functional/testcases.py", line 89, in runTest
    tc.find('<form class="newticket" method="get" '
  File "/run/shm/12cdd65075279a8db3acc4d920ed8fd0b3a2cbb1/py27-sqlite/trac/tests/functional/better_twill.py", line 229, in better_find
    (to_unicode(e), filename))
TwillAssertionError: no match to '<form class="newticket" method="get" action="http://trac-hacks.org/newticket">' at file:///run/shm/12cdd65075279a8db3acc4d920ed8fd0b3a2cbb1/py27-sqlite/testenv/trac/log/TestErrorPage.html

======================================================================
FAIL: runTest (trac.tests.functional.testcases.RegressionTestTicket11434)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/run/shm/12cdd65075279a8db3acc4d920ed8fd0b3a2cbb1/py27-sqlite/trac/tests/functional/testcases.py", line 342, in runTest
    tc.find('<form class="newticket" method="get" '
  File "/run/shm/12cdd65075279a8db3acc4d920ed8fd0b3a2cbb1/py27-sqlite/trac/tests/functional/better_twill.py", line 229, in better_find
    (to_unicode(e), filename))
TwillAssertionError: no match to '<form class="newticket" method="get" action="http://trac-hacks.org/newticket">' at file:///run/shm/12cdd65075279a8db3acc4d920ed8fd0b3a2cbb1/py27-sqlite/testenv/trac/log/RegressionTestTicket11434.html

----------------------------------------------------------------------
Ran 217 tests in 267.780s

FAILED (failures=2)

Also, I don't think we should use raise e! The stack trace of exception would be changed by re-raising.

>>> import traceback
>>> try:
...   try:
...     raise ValueError('***')
...   except ValueError as e:
...     traceback.print_exc()
...     raise e
... except ValueError as e2:
...   traceback.print_exc()
...
Traceback (most recent call last):
  File "<stdin>", line 3, in <module>
ValueError: ***
Traceback (most recent call last):
  File "<stdin>", line 6, in <module>
ValueError: ***

If we indeed re-raise a caught exception, I think we should use err = sys.exc_info() and raise err[0], err[1], err[2].

[Ryan J Ollos]

Replying to Jun Omae:

If we indeed re-raise a caught exception, I think we should use err = sys.exc_info() and raise err[0], err[1], err[2].

I was thinking that's an older form of exception raising according to ​PEP8, even though it's doesn't explicitly call out this 3 expression form.

When raising an exception in Python 2, use raise ValueError('message') instead of the older form raise ValueError, 'message'

I guess we would normally use raise:

>>> try:
...   try:
...     raise ValueError('**')
...   except ValueError as e:
...     traceback.print_exc()
...     raise
... except ValueError as e2:
...   traceback.print_exc()
... 
Traceback (most recent call last):
  File "<stdin>", line 3, in <module>
ValueError: **
Traceback (most recent call last):
  File "<stdin>", line 3, in <module>
ValueError: **

>>> try:
...   try:
...     raise ValueError('**')
...   except ValueError as e:
...     traceback.print_exc()
...     err = sys.exc_info()
...     raise err[0], err[1], err[2]
... except ValueError as e2:
...   traceback.print_exc()
... 
Traceback (most recent call last):
  File "<stdin>", line 3, in <module>
ValueError: **
Traceback (most recent call last):
  File "<stdin>", line 3, in <module>
ValueError: **

but that won't work in this case because of the inner exception. I guess there is nothing wrong with the ​3 expression form and it is appropriate for this use case.

[Ryan J Ollos]

Replying to Jun Omae:

Functional tests has 2 failures. How about simply raising a TracError instead of NotImplementedError?

Do you mean, raise TracError instead of TracNotImplementedError, or that plugins should modify their code to raise TracError rather than NotImplementedError?

[Ryan J Ollos]

I committed the refactoring in [14604], with changes suggested in comment:2. I'll rework the other changes.

[Jun Omae]

Looking [14604], if no reason, we should use except ExceptionName as e rather than if isinstance(e, ExceptionName).

trac/web/main.py

@@ -275 +275 @@
                 self._post_process_request(req)
         except RequestDone:
             raise
-        except Exception as e:
+        except PermissionError as e:
+            raise HTTPForbidden(e)
+        except ResourceNotFound as e:
+            raise HTTPNotFound(e)
+        except TracError as e:
+            raise HTTPInternalError(e)
+        except Exception:
             # post-process the request in case of errors
             err = sys.exc_info()
             try:
                 self._post_process_request(req)
             except RequestDone:
                 pass
-            except Exception as e2:
+            except Exception as e:
                 self.log.error("Exception caught while post-processing"
                                " request: %s",
-                               exception_to_unicode(e2, traceback=True))
-            if isinstance(e, PermissionError):
-                raise HTTPForbidden(e)
-            elif isinstance(e, ResourceNotFound):
-                raise HTTPNotFound(e)
-            elif isinstance(e, TracError):
-                raise HTTPInternalError(e)
-            else:
-                raise err[0], err[1], err[2]
+                               exception_to_unicode(e, traceback=True))
+            raise err[0], err[1], err[2]
 
     # ITemplateProvider methods
 

[Ryan J Ollos]

Previously though, self._post_process_request would be called even in case of PermissionError, ResourceNotFound and TracError. It appears that wouldn't be the case with proposed changes. I might be wrong about that. The old behavior was very confusing with so many nested control structures.

I think it's a better easier to see changes in this diff view.

[Jun Omae]

Replying to Ryan J Ollos:

Previously though, self._post_process_request would be called even in case of PermissionError, ResourceNotFound and TracError. It appears that wouldn't be the case with proposed changes. I might be wrong about that. The old behavior was very confusing with so many nested control structures.

I think it's a better easier to see changes in this diff view.

Yeah, removing nested try/except in [14604] looks good but I dislike isinstance(e, ExceptionName) in except block. Please ignore the diff in comment:6, sorry.

[Jun Omae]

Replying to Ryan J Ollos:

Replying to Jun Omae:

Functional tests has 2 failures. How about simply raising a TracError instead of NotImplementedError?

Do you mean, raise TracError instead of TracNotImplementedError, or that plugins should modify their code to raise TracError rather than NotImplementedError?

I misunderstood. I agree adding NotImplementedError. Reconsidering, I think the Trac administrators want to know where does the NotImplementedError come from. How about logging last entry of the stacktrace?

trac/web/main.py

@@ -30 +30 @@
 from pprint import pformat, pprint
 import re
 import sys
+import traceback
 
 from genshi.builder import tag
 from genshi.output import DocType
@@ -288 +289 @@
                                exception_to_unicode(e2, traceback=True))
             if isinstance(e, PermissionError):
                 raise HTTPForbidden(e)
-            elif isinstance(e, ResourceNotFound):
+            if isinstance(e, ResourceNotFound):
                 raise HTTPNotFound(e)
-            elif isinstance(e, TracError):
+            if isinstance(e, NotImplementedError):
+                tb = traceback.extract_tb(err[2])[-1]
+                self.log.warning('%s caught from %s:%d in %s: %s',
+                                 e.__class__.__name__, tb[0], tb[1], tb[2],
+                                 to_unicode(e) or '(no message)')
+                raise HTTPInternalError(TracNotImplementedError(e))
+            if isinstance(e, TracError):
                 raise HTTPInternalError(e)
-            else:
-                raise err[0], err[1], err[2]
+            raise err[0], err[1], err[2]
 
     # ITemplateProvider methods
 

[Ryan J Ollos]

Replying to Jun Omae:

Yeah, removing nested try/except in [14604] looks good but I dislike isinstance(e, ExceptionName) in except block.

Yeah, I dislike it as well. So far I didn't see a better way, but I'll continue to look for ideas for additional refactoring.

[Ryan J Ollos]

Replying to Jun Omae:

I misunderstood. I agree adding NotImplementedError. Reconsidering, I think the Trac administrators want to know where does the NotImplementedError come from. How about logging last entry of the stacktrace?

That's a good idea. I've prepared changes:

• log:rjollos.git:t12385_trap_not_implemented_1.0-stable.1
• log:rjollos.git:t12385_trap_not_implemented_trunk.1

[Jun Omae]

rjollos.git@t12385_trap_not_implemented_1.0-stable.1 has a syntax error for Python 2.5.

python ./trac/test.py --skip-functional-tests 
/run/shm/e51b3da7994bf506a2f6d42e4d9d7c48b204e28a/py25-sqlite/trac/web/tests/main.py:241: Warning: 'as' will become a reserved keyword in Python 2.6
Traceback (most recent call last):
..
  File "/run/shm/e51b3da7994bf506a2f6d42e4d9d7c48b204e28a/py25-sqlite/trac/web/tests/main.py", line 241
    except HTTPInternalError as e:
                              ^
SyntaxError: invalid syntax
make: *** [unit-test] Error 1

[Jun Omae]

When generating navigation items from INavigationContributor components, exceptions from the components is logged without stacktrace. See tags/trac-1.0.10/trac/web/chrome.py@:811-816#L809​. I think the behavior makes difficult debugging/trouble shooting.

The logging last entry of the stacktrace might help the debugging/trouble shooting in the case. Thoughts?

[Ryan J Ollos]

Replying to Jun Omae:

The logging last entry of the stacktrace might help the debugging/trouble shooting in the case. Thoughts?

Logging the stacktrace is a good idea. The Error with navigation contributor is raised on the mailing list fairly often and it's difficult to debug the problem.

[Ryan J Ollos]

I addressed the errors in comment:12 (thanks!), then comment:11 changes committed to 1.0-stable in [14618], merged to trunk in [14619].

I'll leave the ticket open to address comment:13, unless we want to have a different ticket for that.

[Ryan J Ollos]

Similar to comment:13, I ran into an issue today in which the following error was displayed:

I think the issue is caused by ​SearchAttachmentsPlugin. This is what was logged:

2016-03-21 11:54:06,157 Trac[main] WARNING: [96.93.126.65] HTTPInternalError: 500 Trac Error (Genshi UnicodeDecodeError error while rendering template 'search.html', line 63, char 77)

This Trac instance has:

[trac]
use_chunked_encoding = false

Is there a reason that the stacktrace isn't printed for this case?: tags/trac-1.0.10/trac/web/chrome.py@:1130-1133#L1108​

The stacktrace is printed when use_chunked_encoding?: tags/trac-1.0.10/trac/web/chrome.py@:1188-1190#L1165​

[Ryan J Ollos]

Replying to Ryan J Ollos:

Replying to Jun Omae:

The logging last entry of the stacktrace might help the debugging/trouble shooting in the case. Thoughts?

Logging the stacktrace is a good idea. The Error with navigation contributor is raised on the mailing list fairly often and it's difficult to debug the problem.

​gmessage:trac-users:rDT7ljOFcm4/gcgX3vqeCwAJ is one such case, from what I remember.

[Jun Omae]

Replying to Ryan J Ollos:

Is there a reason that the stacktrace isn't printed for this case?: tags/trac-1.0.10/trac/web/chrome.py@:1130-1133#L1108​

That code is introduced in [7838] (#7959). Perhaps, the reason is the printing stacktrace doesn't help because the UnicodeError is raised from genshi/core.py in most cases if the UnicodeError is raised while rendering genshi template.

However, it would be good to log the stacktrace before raising a converted TracError.

The stacktrace is printed when use_chunked_encoding?: tags/trac-1.0.10/trac/web/chrome.py@:1188-1190#L1165​

I forget the reason…. Maybe, I considered we should log the error with stacetrace since caught exception isn't converted to TracError.

[Ryan J Ollos]

Documented TracNotImplementedError in TracDev/Exceptions@17. I should probably add a docstring to the TracNotImplementedError class.

[Ryan J Ollos]

Replying to Ryan J Ollos:

Similar to comment:13, I ran into an issue today in which the following error was displayed:

Might not be directly related to what we are discussing in this ticket, but as a side note I changed use_chunked_encoding to true and no longer see the error described in comment:16.

[Ryan J Ollos]

Replying to Ryan J Ollos:

Documented TracNotImplementedError in TracDev/Exceptions@17. I should probably add a docstring to the TracNotImplementedError class.

Documented in [14670], merged to trunk in [14671].

[Ryan J Ollos]

comment:13, and possibly comment:16, can be addressed in #12428.

[Ryan J Ollos]

Additional changes in [14672,14674,14676] on 1.0-stable, and [14673,14675,14677] on trunk. Sorry for the noise, I'll be more careful in the future.

[Ryan J Ollos]

See #12818 for possible regression in r14604.