Edgewall Software
Modify

Opened 4 years ago

Closed 4 years ago

Last modified 4 years ago

#12632 closed defect (fixed)

TracError while post-processing leads noisy logging

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

TracError while post-processing is logged without traceback.

API Changes:
Internal Changes:

Description (last modified by 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

    diff --git a/trac/web/main.py b/trac/web/main.py
    index 34a43039c..6406f54b3 100644
    a b class RequestDispatcher(Component):  
    280280                except RequestDone:
    281281                    raise
    282282                except Exception, e:
    283                     self.log.error("Exception caught while post-processing"
    284                                    " request: %s",
    285                                    exception_to_unicode(e, traceback=True))
     283                    self.log.error(
     284                        "Exception caught while post-processing request: %s",
     285                        exception_to_unicode(
     286                            e, traceback=not isinstance(TracError, e)))
    286287                raise err[0], err[1], err[2]
    287288        except PermissionError, e:
    288289            raise HTTPForbidden(e)

Attachments (0)

Change History (20)

comment:1 by Jun Omae, 4 years ago

Or:

  • trac/web/main.py

    diff --git a/trac/web/main.py b/trac/web/main.py
    index 34a43039c..9820472f9 100644
    a b class RequestDispatcher(Component):  
    280280                except RequestDone:
    281281                    raise
    282282                except Exception, e:
    283                     self.log.error("Exception caught while post-processing"
    284                                    " request: %s",
    285                                    exception_to_unicode(e, traceback=True))
     283                    if isinstance(e, TracError):
     284                        self.log.warning("Exception caught while"
     285                                         " post-processing request: %s",
     286                                         exception_to_unicode(e))
     287                    else:
     288                        self.log.error("Exception caught while post-processing"
     289                                       " request: %s",
     290                                       exception_to_unicode(e, traceback=True))
    286291                raise err[0], err[1], err[2]
    287292        except PermissionError, e:
    288293            raise HTTPForbidden(e)
Last edited 4 years ago by Jun Omae (previous) (diff)

comment:2 by Jun Omae, 4 years ago

Description: modified (diff)

comment:3 by Ryan J Ollos, 4 years ago

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.

comment:4 by Jun Omae, 4 years ago

Milestone: next-stable-1.0.x1.2.1
Owner: set to Jun Omae
Status: newassigned

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

comment:5 by Ryan J Ollos, 4 years ago

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.

comment:6 by Jun Omae, 4 years ago

Milestone: 1.2.11.0.14
Release Notes: modified (diff)
Resolution: fixed
Status: assignedclosed

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

comment:7 by Ryan J Ollos, 4 years ago

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?

comment:8 by Jun Omae, 4 years ago

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

  • trac/web/main.py

    diff --git a/trac/web/main.py b/trac/web/main.py
    index ce2e81437..42aea7bda 100644
    a b def _dispatch_request(req, env, env_error):  
    578578def _send_user_error(req, env, e):
    579579    # See trac/web/api.py for the definition of HTTPException subclasses.
    580580    if env:
    581         env.log.warn('[%s] %s', req.remote_addr, exception_to_unicode(e))
     581        env.log.warning('[%s] %s, %r, referrer %r',
     582                        req.remote_addr, exception_to_unicode(e), req,
     583                        req.environ.get('HTTP_REFERER'))
    582584    data = {'title': e.title, 'type': 'TracError', 'message': e.message,
    583585            'frames': [], 'traceback': None}
    584586    if e.code == 403 and req.authname == 'anonymous':
    def _send_user_error(req, env, e):  
    594596
    595597def send_internal_error(env, req, exc_info):
    596598    if env:
    597         env.log.error("Internal Server Error: %r, referrer %r%s",
    598                       req, req.environ.get('HTTP_REFERER'),
     599        env.log.error("[%s] Internal Server Error: %r, referrer %r%s",
     600                      req.remote_addr, req, req.environ.get('HTTP_REFERER'),
    599601                      exception_to_unicode(exc_info[1], traceback=True))
    600602    message = exception_to_unicode(exc_info[1])
    601603    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

comment:9 by Ryan J Ollos, 4 years ago

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

comment:10 by Ryan J Ollos, 4 years ago

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?

Last edited 4 years ago by Ryan J Ollos (previous) (diff)

comment:11 by Ryan J Ollos, 4 years ago

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

    diff --git a/trac/web/main.py b/trac/web/main.py
    index b0680ab5b..20dcd35c9 100644
    a b class RequestDispatcher(Component):  
    289289                if isinstance(e, TracError):
    290290                    self.log.warning("Exception caught while post-processing"
    291291                                     " request: %s", exception_to_unicode(e2))
    292                 else:
     292                elif not HTTPException:
    293293                    self.log.error("Exception caught while post-processing"
    294294                                   " request: %s",
    295295                                   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

comment:12 by Jun Omae, 4 years ago

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))

in reply to:  11 ; comment:13 by Jun Omae, 4 years ago

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

    diff --git a/trac/web/main.py b/trac/web/main.py
    index b0680ab5b..20dcd35c9 100644
    a b class RequestDispatcher(Component):  
    289289                if isinstance(e, TracError):
    290290                    self.log.warning("Exception caught while post-processing"
    291291                                     " request: %s", exception_to_unicode(e2))
    292                 else:
     292                elif not HTTPException:
    293293                    self.log.error("Exception caught while post-processing"
    294294                                   " request: %s",
    295295                                   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

    diff --git a/trac/web/main.py b/trac/web/main.py
    index b0680ab5b..868b2b62c 100644
    a b class RequestDispatcher(Component):  
    283283            err = sys.exc_info()
    284284            try:
    285285                self._post_process_request(req)
    286             except RequestDone:
     286            except (RequestDone, HTTPException):
    287287                pass
    288288            except Exception as e2:
    289289                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

    diff --git a/trac/web/main.py b/trac/web/main.py
    index b0680ab5b..83894e596 100644
    a b class RequestDispatcher(Component):  
    286286            except RequestDone:
    287287                pass
    288288            except Exception as e2:
    289                 if isinstance(e, TracError):
     289                if isinstance(e2, TracError) or \
     290                        type(e) is type(e2) and e.args == e2.args:
    290291                    self.log.warning("Exception caught while post-processing"
    291292                                     " request: %s", exception_to_unicode(e2))
    292293                else:
Last edited 4 years ago by Jun Omae (previous) (diff)

in reply to:  12 ; comment:14 by Ryan J Ollos, 4 years ago

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.

in reply to:  13 ; comment:15 by Ryan J Ollos, 4 years ago

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.

in reply to:  15 comment:16 by Jun Omae, 4 years ago

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):
Last edited 4 years ago by Jun Omae (previous) (diff)

in reply to:  14 comment:17 by Jun Omae, 4 years ago

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

    diff --git a/trac/web/main.py b/trac/web/main.py
    index b0680ab5b..52a9c7ebf 100644
    a b class RequestDispatcher(Component):  
    285285                self._post_process_request(req)
    286286            except RequestDone:
    287287                pass
     288            except TracError as e2:
     289                self.log.warning("Exception caught while post-processing"
     290                                 " request: %s", exception_to_unicode(e2))
    288291            except Exception as e2:
    289                 if isinstance(e, TracError):
    290                     self.log.warning("Exception caught while post-processing"
    291                                      " request: %s", exception_to_unicode(e2))
    292                 else:
    293                     self.log.error("Exception caught while post-processing"
    294                                    " request: %s",
    295                                    exception_to_unicode(e2, traceback=True))
     292                self.log.error("Exception caught while post-processing"
     293                               " request: %s",
     294                               exception_to_unicode(e2, traceback=True))
    296295            if isinstance(e, PermissionError):
    297296                raise HTTPForbidden(e)
    298297            if isinstance(e, ResourceNotFound):

comment:18 by Ryan J Ollos, 4 years ago

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

With:

  • trac/web/main.py

    diff --git a/trac/web/main.py b/trac/web/main.py
    index 52a9c7ebf..3e112d172 100644
    a b class RequestDispatcher(Component):  
    289289                self.log.warning("Exception caught while post-processing"
    290290                                 " request: %s", exception_to_unicode(e2))
    291291            except Exception as e2:
    292                 self.log.error("Exception caught while post-processing"
    293                                " request: %s",
    294                                exception_to_unicode(e2, traceback=True))
     292                if type(e) is type(e2) and e.args == e2.args:
     293                    self.log.warning("Exception caught while post-processing"
     294                                     " request: %s", exception_to_unicode(e2))
     295                else:
     296                    self.log.error("Exception caught while post-processing"
     297                                   " request: %s",
     298                                   exception_to_unicode(e2, traceback=True))
    295299            if isinstance(e, PermissionError):
    296300                raise HTTPForbidden(e)
    297301            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

    diff --git a/trac/web/main.py b/trac/web/main.py
    index 52a9c7ebf..0ec782c8f 100644
    a b class RequestDispatcher(Component):  
    289289                self.log.warning("Exception caught while post-processing"
    290290                                 " request: %s", exception_to_unicode(e2))
    291291            except Exception as e2:
    292                 self.log.error("Exception caught while post-processing"
    293                                " request: %s",
    294                                exception_to_unicode(e2, traceback=True))
     292                if not (type(e) is type(e2) and e.args == e2.args):
     293                    self.log.error("Exception caught while post-processing"
     294                                   " request: %s",
     295                                   exception_to_unicode(e2, traceback=True))
    295296            if isinstance(e, PermissionError):
    296297                raise HTTPForbidden(e)
    297298            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?

comment:19 by Jun Omae, 4 years ago

The latter looks good to me. Thanks.

comment:20 by Ryan J Ollos, 4 years ago

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

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.