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

[Ryan J Ollos]

Looking at a traceback such as ​th:comment:17:ticket:11869 and considering how to reproduce the error, what do you think about adding req.path_info to the log message?

[Jun Omae]

Sounds good. Also, we could add req.remote_addr to logging when internal error is occurred.

trac/web/main.py

@@ -578 +578 @@
 def _send_user_error(req, env, e):
     # See trac/web/api.py for the definition of HTTPException subclasses.
     if env:
-        env.log.warn('[%s] %s', req.remote_addr, exception_to_unicode(e))
+        env.log.warning('[%s] %s, %r, referrer %r',
+                        req.remote_addr, exception_to_unicode(e), req,
+                        req.environ.get('HTTP_REFERER'))
     data = {'title': e.title, 'type': 'TracError', 'message': e.message,
             'frames': [], 'traceback': None}
     if e.code == 403 and req.authname == 'anonymous':
@@ -594 +596 @@
 
 def send_internal_error(env, req, exc_info):
     if env:
-        env.log.error("Internal Server Error: %r, referrer %r%s",
-                      req, req.environ.get('HTTP_REFERER'),
+        env.log.error("[%s] Internal Server Error: %r, referrer %r%s",
+                      req.remote_addr, req, req.environ.get('HTTP_REFERER'),
                       exception_to_unicode(exc_info[1], traceback=True))
     message = exception_to_unicode(exc_info[1])
     traceback = get_last_traceback()

2016-12-09 18:52:18,854 Trac[main] WARNING: Exception caught while post-processing request: TracError: #12632
2016-12-09 18:52:18,854 Trac[main] WARNING: [192.168.11.21] HTTPInternalError: 500 Trac Error (#12632), <RequestWithSession "GET '/admin'">, referrer None

2016-12-09 18:52:46,975 Trac[main] ERROR: Exception caught while post-processing request:
Traceback (most recent call last):
  File "/src/tracdev/git/trac/web/main.py", line 279, in dispatch
    self._post_process_request(req)
  File "/src/tracdev/git/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-09 18:52:46,976 Trac[main] ERROR: [192.168.11.21] Internal Server Error: <RequestWithSession "GET '/admin'">, referrer None
Traceback (most recent call last):
  File "/src/tracdev/git/trac/web/main.py", line 567, in _dispatch_request
    dispatcher.dispatch(req)
  File "/src/tracdev/git/trac/web/main.py", line 259, in dispatch
    self._post_process_request(req, *resp)
  File "/src/tracdev/git/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

[Ryan J Ollos]

Thanks for suggestions. Committed to 1.0-stable in r15361, merged in r15362 and r15363.

[Ryan J Ollos]

Recently I've been seeing this traceback in the logs:

[pid 9560 140352200652544] 2017-02-12 05:50:01,137 Trac[main] ERROR: Exception caught while post-processing request: 
Traceback (most recent call last):
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 286, in dispatch
    self._post_process_request(req)
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 463, in _post_process_request
    f.post_process_request(req, *(None,) * extra_arg_count)
  File "build/bdist.linux-x86_64/egg/trac/ticket/batch.py", line 83, in post_process_request
    if req.path_info == '/query' and \
  File "build/bdist.linux-x86_64/egg/trac/web/api.py", line 581, in path_info
    path_info=path_info))

It looks like incorrect encoding of path_info is raising an exception in post_processing_request of BatchModule and the exception is trapped and logged. Maybe we should just re-raise some or all exceptions that inherit from HTTPException, or at least for HTTPNotFound?

[Ryan J Ollos]

Traceback can be reproduced with a path containing an invalid byte sequence, such as /milestone/%AD:

14:34:02 Trac[main] ERROR: Exception caught while post-processing request: 
Traceback (most recent call last):
  File "/Users/rjollos/Documents/Workspace/trac-dev/teo-rjollos.git/trac/web/main.py", line 285, in dispatch
    self._post_process_request(req)
  File "/Users/rjollos/Documents/Workspace/trac-dev/teo-rjollos.git/trac/web/main.py", line 454, in _post_process_request
    f.post_process_request(req, *(None,)*extra_arg_count)
  File "/Users/rjollos/Documents/Workspace/trac-dev/teo-rjollos.git/trac/ticket/batch.py", line 84, in post_process_request
    if req.path_info == '/query' and \
  File "/Users/rjollos/Documents/Workspace/trac-dev/teo-rjollos.git/trac/web/api.py", line 526, in path_info
    path_info=path_info))
HTTPNotFound: 404 Not Found (Invalid URL encoding (was '/milestone/\xad'))
14:34:02 Trac[main] WARNING: [127.0.0.1] HTTPNotFound: 404 Not Found (Invalid URL encoding (was '/milestone/\xad')), <RequestWithSession "GET '/milestone/\xad'">, referrer None

With this patch:

trac/web/main.py

@@ -289 +289 @@
                 if isinstance(e, TracError):
                     self.log.warning("Exception caught while post-processing"
                                      " request: %s", exception_to_unicode(e2))
-                else:
+                elif not HTTPException:
                     self.log.error("Exception caught while post-processing"
                                    " request: %s",
                                    exception_to_unicode(e2, traceback=True))

log message would be:

14:34:39 Trac[main] WARNING: [127.0.0.1] HTTPNotFound: 404 Not Found (Invalid URL encoding (was '/milestone/\xad')), <RequestWithSession "GET '/milestone/\xad'">, referrer None

[Jun Omae]

The following line is weird.

             except Exception as e2:
-                if isinstance(e, TracError):
+                if isinstance(e2, TracError):
                     self.log.warning("Exception caught while post-processing"
                                      " request: %s", exception_to_unicode(e2))

[Jun Omae]

Replying to Ryan J Ollos:

Traceback can be reproduced with a path containing an invalid byte sequence, such as /milestone/%AD:

[…]

With this patch:

trac/web/main.py

@@ -289 +289 @@
                 if isinstance(e, TracError):
                     self.log.warning("Exception caught while post-processing"
                                      " request: %s", exception_to_unicode(e2))
-                else:
+                elif not HTTPException:
                     self.log.error("Exception caught while post-processing"
                                    " request: %s",
                                    exception_to_unicode(e2, traceback=True))

I don't think we should just ignore the exception while post-processing. However, if you'd like to ignore it, it would be simple like this:

trac/web/main.py

@@ -283 +283 @@
             err = sys.exc_info()
             try:
                 self._post_process_request(req)
-            except RequestDone:
+            except (RequestDone, HTTPException):
                 pass
             except Exception as e2:
                 if isinstance(e, TracError):

This noisy logging is lead when the same exception is raised from pre_process_request/process_request and post_process_request. In the case, we could log the exception without traceback or ignore.

trac/web/main.py

@@ -286 +286 @@
             except RequestDone:
                 pass
             except Exception as e2:
-                if isinstance(e, TracError):
+                if isinstance(e2, TracError) or \
+                        type(e) is type(e2) and e.args == e2.args:
                     self.log.warning("Exception caught while post-processing"
                                      " request: %s", exception_to_unicode(e2))
                 else:

[Ryan J Ollos]

Replying to Jun Omae:

The following line is weird.

             except Exception as e2:
-                if isinstance(e, TracError):
+                if isinstance(e2, TracError):
                     self.log.warning("Exception caught while post-processing"
                                      " request: %s", exception_to_unicode(e2))

That appears to be due to the merge in r15291.

[Ryan J Ollos]

Replying to Jun Omae:

I don't think we should just ignore the exception while post-processing.

I'm not suggesting we ignore it, I'm suggesting it doesn't need to get logged with traceback because we can allow the exception to propagate and it will be logged as shown in comment:11.

[Jun Omae]

Replying to Ryan J Ollos:

Replying to Jun Omae:

I don't think we should just ignore the exception while post-processing.

I'm not suggesting we ignore it, I'm suggesting it doesn't need to get logged with traceback because we can allow the exception to propagate and it will be logged as shown in comment:11.

I think we should check whether e and e2 are same if we'd like to do it.

Also, I think that elif not HTTPException is programming error. The following line in comment:11 should be:

-                elif not HTTPException:
+                elif not isinstance(e2, HTTPException):

[Jun Omae]

Replying to Ryan J Ollos:

Replying to Jun Omae:

The following line is weird.

             except Exception as e2:
-                if isinstance(e, TracError):
+                if isinstance(e2, TracError):
                     self.log.warning("Exception caught while post-processing"
                                      " request: %s", exception_to_unicode(e2))

That appears to be due to the merge in r15291.

Ahh, my bad. isinstance(e, exception-type) in except statements is bad pattern.

trac/web/main.py

@@ -285 +285 @@
                 self._post_process_request(req)
             except RequestDone:
                 pass
+            except TracError as e2:
+                self.log.warning("Exception caught while post-processing"
+                                 " request: %s", exception_to_unicode(e2))
             except Exception as e2:
-                if isinstance(e, TracError):
-                    self.log.warning("Exception caught while post-processing"
-                                     " request: %s", exception_to_unicode(e2))
-                else:
-                    self.log.error("Exception caught while post-processing"
-                                   " request: %s",
-                                   exception_to_unicode(e2, traceback=True))
+                self.log.error("Exception caught while post-processing"
+                               " request: %s",
+                               exception_to_unicode(e2, traceback=True))
             if isinstance(e, PermissionError):
                 raise HTTPForbidden(e)
             if isinstance(e, ResourceNotFound):

[Ryan J Ollos]

That looks good. Changes committed to 1.2-stable in r15624, merged to trunk in r15625.

With:

trac/web/main.py

@@ -289 +289 @@
                 self.log.warning("Exception caught while post-processing"
                                  " request: %s", exception_to_unicode(e2))
             except Exception as e2:
-                self.log.error("Exception caught while post-processing"
-                               " request: %s",
-                               exception_to_unicode(e2, traceback=True))
+                if type(e) is type(e2) and e.args == e2.args:
+                    self.log.warning("Exception caught while post-processing"
+                                     " request: %s", exception_to_unicode(e2))
+                else:
+                    self.log.error("Exception caught while post-processing"
+                                   " request: %s",
+                                   exception_to_unicode(e2, traceback=True))
             if isinstance(e, PermissionError):
                 raise HTTPForbidden(e)
             if isinstance(e, ResourceNotFound):

the following will be logged:

22:34:37 Trac[main] WARNING: Exception caught while post-processing request: HTTPNotFound: 404 Not Found (Invalid URL encoding (was '/milestone/\xad'))
22:34:37 Trac[main] WARNING: [127.0.0.1] HTTPNotFound: 404 Not Found (Invalid URL encoding (was '/milestone/\xad')), <RequestWithSession "GET '/milestone/\xad'">, referrer None

With:

trac/web/main.py

@@ -289 +289 @@
                 self.log.warning("Exception caught while post-processing"
                                  " request: %s", exception_to_unicode(e2))
             except Exception as e2:
-                self.log.error("Exception caught while post-processing"
-                               " request: %s",
-                               exception_to_unicode(e2, traceback=True))
+                if not (type(e) is type(e2) and e.args == e2.args):
+                    self.log.error("Exception caught while post-processing"
+                                   " request: %s",
+                                   exception_to_unicode(e2, traceback=True))
             if isinstance(e, PermissionError):
                 raise HTTPForbidden(e)
             if isinstance(e, ResourceNotFound):

logging will be:

22:37:17 Trac[main] WARNING: [127.0.0.1] HTTPNotFound: 404 Not Found (Invalid URL encoding (was '/milestone/\xad')), <RequestWithSession "GET '/milestone/\xad'">, referrer None

Is the latter patch good enough?

[Jun Omae]

The latter looks good to me. Thanks.

[Ryan J Ollos]

Thanks, committed to 1.2-stable in r15630, merged to trunk in r15631.