Modify

Opened 9 years ago

Closed 8 years ago

Last modified 8 years ago

#12408 closed defect (fixed)

Numerous tracebacks in the log

Reported by: Ryan J Ollos Owned by: jomae
Priority: normal Component: XmlRpcPlugin
Severity: normal Keywords:
Cc: Trac Release:

Description (last modified by Jun Omae)

I'm frequently seeing tracebacks in the logs, presumable due to invalid input from bots. I'd like to see if there are simple changes we can make to avoid uncaught exceptions.

Here are some samples:

2015-05-11 10:04:51,726 Trac[web_ui] ERROR: RPC(XML-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 143, in _rpc_process
    rpcreq = req.rpc = protocol.parse_rpc_request(req, content_type)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/xml_rpc.py", line 118, in parse_rpc_request
    raise ProtocolException(xmlrpclib.Fault(-32700, to_unicode(e)))
ProtocolException: <Fault -32700: u"int() argument must be a string or a number, not 'NoneType'">
2015-05-11 10:04:52,321 Trac[web_ui] ERROR: RPC(XML-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 143, in _rpc_process
    rpcreq = req.rpc = protocol.parse_rpc_request(req, content_type)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/xml_rpc.py", line 118, in parse_rpc_request
    raise ProtocolException(xmlrpclib.Fault(-32700, to_unicode(e)))
ProtocolException: <Fault -32700: u"int() argument must be a string or a number, not 'NoneType'">
2015-09-16 13:10:55,566 Trac[web_ui] ERROR: RPC(XML-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 143, in _rpc_process
    rpcreq = req.rpc = protocol.parse_rpc_request(req, content_type)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/xml_rpc.py", line 118, in parse_rpc_request
    raise ProtocolException(xmlrpclib.Fault(-32700, to_unicode(e)))
ProtocolException: <Fault -32700: u'no element found: line 1, column 0'>
2015-06-18 09:38:29,733 Trac[json_rpc] ERROR: RPC(json) decode error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/json_rpc.py", line 162, in parse_rpc_request
    data = json.load(req, cls=TracRpcJSONDecoder)
  File "/usr/lib/python2.6/json/__init__.py", line 267, in load
    parse_constant=parse_constant, **kw)
  File "/usr/lib/python2.6/json/__init__.py", line 318, in loads
    return cls(encoding=encoding, **kw).decode(s)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/json_rpc.py", line 113, in decode
    obj = json.JSONDecoder.decode(self, obj, *args, **kwargs)
  File "/usr/lib/python2.6/json/decoder.py", line 319, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python2.6/json/decoder.py", line 338, in raw_decode
    raise ValueError("No JSON object could be decoded")
ValueError: No JSON object could be decoded
2016-08-01 11:44:23,937 Trac[json_rpc] ERROR: RPC(json) decode error 
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/json_rpc.py", line 162, in parse_rpc_request
    data = json.load(req, cls=TracRpcJSONDecoder)
  File "/usr/lib/python2.7/json/__init__.py", line 290, in load
    **kw)
  File "/usr/lib/python2.7/json/__init__.py", line 351, in loads
    return cls(encoding=encoding, **kw).decode(s)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/json_rpc.py", line 113, in decode
    obj = json.JSONDecoder.decode(self, obj, *args, **kwargs)
  File "/usr/lib/python2.7/json/decoder.py", line 366, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python2.7/json/decoder.py", line 382, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Expecting property name: line 1 column 2 (char 1)
2016-08-01 11:44:23,945 Trac[web_ui] ERROR: RPC(JSON-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/web_ui.py", line 143, in _rpc_process
    rpcreq = req.rpc = protocol.parse_rpc_request(req, content_type)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/json_rpc.py", line 176, in parse_rpc_request
    raise JsonProtocolException(e, -32700)
JsonProtocolException: Expecting property name: line 1 column 2 (char 1)
2015-11-03 02:07:24,240 Trac[web_ui] ERROR: RPC(JSON-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 143, in _rpc_process
    rpcreq = req.rpc = protocol.parse_rpc_request(req, content_type)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/json_rpc.py", line 176, in parse_rpc_request
    raise JsonProtocolException(e, -32700)
JsonProtocolException: No JSON object could be decoded
2015-06-18 09:57:54,830 Trac[web_ui] ERROR: RPC(JSON-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/api.py", line 197, in __call__
    result = self.callable(req, *args)
ServiceException: getAll() takes exactly 2 arguments (3 given)
2015-08-18 18:42:24,931 Trac[web_ui] ERROR: RPC(XML-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/api.py", line 197, in __call__
    result = self.callable(req, *args)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/ticket.py", line 149, in get
    t = model.Ticket(self.env, id)
  File "build/bdist.linux-i686/egg/trac/ticket/model.py", line 85, in __init__
    self._fetch_ticket(tkt_id)
  File "build/bdist.linux-i686/egg/trac/ticket/model.py", line 124, in _fetch_ticket
    id=tkt_id), _("Invalid ticket number"))
ResourceNotFound: Ticket 0 does not exist.
2016-03-17 14:02:10,087 Trac[web_ui] ERROR: RPC(JSON-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/api.py", line 197, in __call__
    result = self.callable(req, *args)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/wiki.py", line 109, in getPage
    page = self._fetch_page(req, pagename, version)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/wiki.py", line 71, in _fetch_page
    raise ResourceNotFound(msg)
ResourceNotFound: Wiki page "ClansuiteTeam" does not exist
2016-03-17 14:02:10,734 Trac[web_ui] ERROR: RPC(JSON-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/api.py", line 197, in __call__
    result = self.callable(req, *args)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/ticket.py", line 400, in get
    i = cls(self.env, name)
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/ticket/model.py", line 1002, in __init__
    name=name), _("Invalid milestone name"))
ResourceNotFound: Milestone Clansuite 0.2.2 does not exist.
2015-08-17 15:18:28,828 Trac[web_ui] ERROR: RPC(XML-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/api.py", line 286, in get_method
    raise MethodNotFound('RPC method "%s" not found' % method)
MethodNotFound: RPC method "wikiext.getChildren" not found
2016-01-06 13:40:37,804 Trac[web_ui] ERROR: RPC(XML-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/api.py", line 286, in get_method
    raise MethodNotFound('RPC method "%s" not found' % method)
MethodNotFound: RPC method "system.ticket.__repr__" not found
2016-01-06 13:40:44,529 Trac[web_ui] ERROR: RPC(XML-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/api.py", line 286, in get_method
    raise MethodNotFound('RPC method "%s" not found' % method)
MethodNotFound: RPC method "system.ticket.create" not found}
2015-09-15 07:12:49,986 Trac[web_ui] ERROR: RPC(JSON-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/api.py", line 197, in __call__
    result = self.callable(req, *args)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/api.py", line 339, in getAPIVersion
    return map(int, tracrpc.__version__.split('-')[0].split('.'))
ServiceException: invalid literal for int() with base 10: 'post13776'
2015-12-18 16:39:33,790 Trac[web_ui] ERROR: RPC(XML-RPC) Error
Traceback (most recent call last):  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 158, in _rpc_process    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/api.py", line 197, in __call__
    result = self.callable(req, *args)  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/api.py", line 339, in getAPIVersion    return map(int, tracrpc.__version__.split('-')[0].split('.'))
ServiceException: invalid literal for int() with base 10: 'post13776'
2015-12-18 16:39:33,801 Trac[xml_rpc] ERROR: invalid literal for int() with base 10: 'post13776'2015-12-18 16:39:33,801 Trac[xml_rpc] ERROR: Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13
776-py2.6.egg/tracrpc/api.py", line 197, in __call__
    result = self.callable(req, *args)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracXMLRPC-1.1.2_r13776-py2.6.egg/tracrpc/api.py", line 339, in getAPIVersion
    return map(int, tracrpc.__version__.split('-')[0].split('.'))
ServiceException: invalid literal for int() with base 10: 'post13776'
2016-01-06 13:41:11,666 Trac[xml_rpc] ERROR: create() takes at least 4 arguments (2 given)
2016-01-06 13:41:11,666 Trac[xml_rpc] ERROR: Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/api.py", line 197, in __call__
    result = self.callable(req, *args)
ServiceException: create() takes at least 4 arguments (2 given)
2016-10-05 19:32:45,666 Trac[web_ui] ERROR: RPC(XML-RPC) Error
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/tracrpc/web_ui.py", line 149, in _rpc_process
    req.perm.require('XML_RPC') # Need at least XML_RPC
  File "/srv/trac-hacks.org/pve/lib/python2.7/site-packages/trac/perm.py", line 587, in require
    raise PermissionError(action, resource, self.env)
PermissionError: XML_RPC privileges are required to perform this operation. You don't have the required permissions.
2016-08-25 08:56:18,490 (7f0946c09700) ERROR: RPC(JSON-RPC) Error
Traceback (most recent call last):
  File "/vol/releases/20160818034305/share/plugins/TracXMLRPC.egg/tracrpc/web_ui.py", line 155, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/vol/releases/20160818034305/share/plugins/TracXMLRPC.egg/tracrpc/api.py", line 209, in __call__
    result = self.callable(req, *args)
  File "/vol/releases/20160818034305/share/plugins/TracXMLRPC.egg/tracrpc/ticket.py", line 74, in query
    q = query.Query.from_string(self.env, qstr)
  File "/usr/local/tracfarm/lib/python2.6/site-packages/trac/ticket/query.py", line 169, in from_string
    raise QuerySyntaxError(_('Query filter requires field and '
ServiceException: ServiceException details : \u5404\u30d5\u30a3\u30eb\u30bf\u306f\u3001\u30d5\u30a3\u30fc\u30eb\u30c9\u306e\u540d\u524d\u3068\u6761\u4ef6\u304c "=" \u3067\u533a\u5207\u308b\u5fc5\u8981\u304c\u3042\u308a\u307e\u3059

See also #11799.

I haven't looked at the code yet, but I hope to provide a patch soon.

Attachments (0)

Change History (17)

comment:2 Changed 9 years ago by Ryan J Ollos

Description: modified (diff)

comment:3 Changed 9 years ago by Ryan J Ollos

Description: modified (diff)

comment:4 Changed 9 years ago by Ryan J Ollos

Description: modified (diff)

comment:5 Changed 9 years ago by Ryan J Ollos

Description: modified (diff)

comment:6 Changed 9 years ago by Ryan J Ollos

Description: modified (diff)

comment:7 Changed 9 years ago by Ryan J Ollos

Description: modified (diff)

comment:8 Changed 9 years ago by Ryan J Ollos

Description: modified (diff)

comment:9 Changed 9 years ago by Ryan J Ollos

Description: modified (diff)

comment:10 Changed 9 years ago by Ryan J Ollos

Description: modified (diff)

comment:11 Changed 8 years ago by Ryan J Ollos

Description: modified (diff)

comment:12 Changed 8 years ago by Ryan J Ollos

Description: modified (diff)

comment:13 Changed 8 years ago by Jun Omae

Description: modified (diff)

comment:14 Changed 8 years ago by Jun Omae

Proposed changes in https://github.com/jun66j5/xmlrpcplugin/commit/t12408.

After the changes, the logging would be like this:

03:29:31 AM Trac[web_ui] WARNING: RPC(XML-RPC) [192.168.11.27] ProtocolException: ProtocolException details : <Fault -32700: u'mismatched tag: line 1, column 37'>
03:30:00 AM Trac[web_ui] WARNING: RPC(XML-RPC) [192.168.11.27] MethodNotFound: RPC method "" not found
03:30:23 AM Trac[web_ui] WARNING: RPC(XML-RPC) [192.168.11.27] ResourceNotFound: Wiki page "WikiStar" does not exist
03:30:54 AM Trac[web_ui] WARNING: RPC(JSON-RPC) [192.168.11.27] MethodNotFound: RPC method "wiki.getPage*" not found
03:31:02 AM Trac[web_ui] WARNING: RPC(JSON-RPC) [192.168.11.27] ResourceNotFound: Wiki page "ikiStart" does not exist
03:31:09 AM Trac[web_ui] WARNING: RPC(JSON-RPC) [192.168.11.27] ServiceException: ServiceException details : getPage() takes at most 4 arguments (6 given)
03:31:34 AM Trac[web_ui] WARNING: RPC(JSON-RPC) [192.168.11.27] QuerySyntaxError: Query filter requires field and constraints separated by a "="
03:31:54 AM Trac[web_ui] WARNING: RPC(JSON-RPC) [192.168.11.27] PermissionError: XML_RPC privileges are required to perform this operation. You don't have the required permissions.
06:21:11 AM Trac[web_ui] ERROR: RPC(JSON-RPC) [192.168.11.27] Exception caught while calling ticket.get(*[u'a']) by admin
Traceback (most recent call last):
  File "/src/xmlrpcplugin.git/tracrpc/web_ui.py", line 158, in _rpc_process
    result = (XMLRPCSystem(self.env).get_method(method_name)(req, args))[0]
  File "/src/xmlrpcplugin.git/tracrpc/api.py", line 197, in __call__
    result = self.callable(req, *args)
  File "/src/xmlrpcplugin.git/tracrpc/ticket.py", line 154, in get
    t = model.Ticket(self.env, id)
  File "/venv/trac/py27/1.0.13/local/lib/python2.7/site-packages/trac/ticket/model.py", line 69, in __init__
    tkt_id = int(tkt_id)
ValueError: invalid literal for int() with base 10: 'a'
Last edited 8 years ago by Jun Omae (previous) (diff)

comment:15 Changed 8 years ago by Ryan J Ollos

Looks good to me. If osimons gives the okay to merge I'll deploy changes to trac-hacks.org.

comment:16 Changed 8 years ago by osimons

If it works for you, then fine by me :-)

comment:17 Changed 8 years ago by Ryan J Ollos

Resolution: fixed
Status: newclosed

In 16228:

XmlRpcPlugin 1.1.6: Fix tracebacks in log file

  • Prevent logging tracebacks when receiving invalid data and log as a warning
  • Log messages without traceback when TracError, PermissionError and ResourceNotFound

Patch by Jun Omae.

Fixes #12408.

comment:18 Changed 8 years ago by Ryan J Ollos

Owner: changed from osimons to jomae

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain jomae.
The resolution will be deleted. Next status will be 'reopened'.

Add Comment


E-mail address and name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.