TracError while post-processing leads noisy logging

[Jun Omae]

TracError while executing process_request() is logged with WARNING level and no traceback. However, same exception while post-processing is logged with ERROR level and traceback. That's noisy….

See ​gmessage:trac-users:4tVRBotYrZs/NB3ZjUYjCAAJ.

trac/web/main.py

@@ -280 +280 @@
                 except RequestDone:
                     raise
                 except Exception, e:
-                    self.log.error("Exception caught while post-processing"
-                                   " request: %s",
-                                   exception_to_unicode(e, traceback=True))
+                    self.log.error(
+                        "Exception caught while post-processing request: %s",
+                        exception_to_unicode(
+                            e, traceback=not isinstance(TracError, e)))
                 raise err[0], err[1], err[2]
         except PermissionError, e:
             raise HTTPForbidden(e)

[Jun Omae]

Or:

trac/web/main.py

@@ -280 +280 @@
                 except RequestDone:
                     raise
                 except Exception, e:
-                    self.log.error("Exception caught while post-processing"
-                                   " request: %s",
-                                   exception_to_unicode(e, traceback=True))
+                    if isinstance(e, TracError):
+                        self.log.warning("Exception caught while"
+                                         " post-processing request: %s",
+                                         exception_to_unicode(e))
+                    else:
+                        self.log.error("Exception caught while post-processing"
+                                       " request: %s",
+                                       exception_to_unicode(e, traceback=True))
                 raise err[0], err[1], err[2]
         except PermissionError, e:
             raise HTTPForbidden(e)

[Ryan J Ollos]

Yeah, I agree we don't need traceback in case of TracError. I think it could be moved to milestone:next-stable-1.2.x.

[Jun Omae]

Okay. I'll push 2nd patch to 1.2-stable branch.

[Ryan J Ollos]

I have no problem if you'd like to push to 1.0-stable, I was just thinking that in general we won't be doing as many fixes on that branch since 1.2 is released. I won't get around to releasing 1.0.14 for at least another 24 hours or so, so the change could be included in that release if you felt it was needed.

[Jun Omae]

Thanks. I reconsider it should be pushed to 1.0-stable. Committed to 1.0-stable in [15290] and merged in [15291-15292].

After [15290], TracError while post-processing is logged like this:

2016-12-07 17:35:17,894 Trac[main] WARNING: Exception caught while post-processing request: TracError: #12632
2016-12-07 17:35:17,894 Trac[main] WARNING: [192.168.11.21] HTTPInternalError: 500 Trac Error (#12632)

Other exceptions while post-processing is logged like this:

2016-12-07 17:38:17,646 Trac[main] ERROR: Exception caught while post-processing request:
Traceback (most recent call last):
  File "/src/tracdev/svn/branches/1.0-stable/trac/web/main.py", line 279, in dispatch
    self._post_process_request(req)
  File "/src/tracdev/svn/branches/1.0-stable/trac/web/main.py", line 403, in _post_process_request
    f.post_process_request(req, *(None,)*extra_arg_count)
  File "/var/trac/1.0-sqlite/plugins/t12632.py", line 12, in post_process_request
    raise TypeError('#12632')
TypeError: #12632
2016-12-07 17:38:17,646 Trac[main] ERROR: Internal Server Error: <RequestWithSession "GET '/about'">, referrer None
Traceback (most recent call last):
  File "/src/tracdev/svn/branches/1.0-stable/trac/web/main.py", line 567, in _dispatch_request
    dispatcher.dispatch(req)
  File "/src/tracdev/svn/branches/1.0-stable/trac/web/main.py", line 259, in dispatch
    self._post_process_request(req, *resp)
  File "/src/tracdev/svn/branches/1.0-stable/trac/web/main.py", line 401, in _post_process_request
    resp = f.post_process_request(req, *resp)
  File "/var/trac/1.0-sqlite/plugins/t12632.py", line 12, in post_process_request
    raise TypeError('#12632')
TypeError: #12632