Features from the xrg dungeons

This series of articles aims to guide you through a set of pending features for OpenERP. Some of them are experimental, some more mature, some need to contain their maturing process... (read more)

Thursday, February 17, 2011

Per-Model Debug (aka. orm._debug)

Original commit: 91c044df57d9e8cfb426e
Rebased commit: db5597aa5097d697ac37
Conceived: 27 Dec 2009
Implemented: Dec 2009
Status: Mature
Git Branch: trunk-xrg, trunk-pg84 (mainly)
Cons: Need explicit code in parts of framework

It is a common situation that we need to have verbose logging of some object operations, in order to trace some bug. But, if we enabled the full debug_rpc output, our needle would be lost in the haystack of million logging lines.
Adding and removing "print" statements in the code is one way, but would only work when we know where to put the "print" line.
Therefore, we define one attribute per ORM object, namely '_debug', which will control verbose logging of that object. If set (to true), the rest of the framework will log in detail the operations related to that model, typically with the DEBUG logging level.
Being formalised, we also have the ability to expose the flag through a special web-services call, so that debugging can conveniently be turned on and off at runtime, without any server restart.
Technically, this is implemented through a '_debug' attribute of the orm_template class. This means that every orm or orm_memory object will have its own _debug value, persistent for the life of a database session.
It is just a boolean flag (actually, other values would be permitted, too)
and can be used in various points where we need to decide if we need verbose logging.
In other words: when we suspect that model "account.brokeness" is doing something wrong, we send an RPC call to set _debug of "account.brokeness", on our live-running server[1][2]. Then, we observe the logging output and see in detail SQL calls, calls to read(), write(), read_flat() and browse() for that object.
Also, if we define some custom code for our model (in python), we can explicitly put debugging statements and leave them there (commit them) without bloating the logs:

if Some-strange-condition:
. if self._debug:
. . logger.debug("Our object has %s" % self.strange_field)

Result: easier distinguish between models, have focused and detailed logs on the objects we are interested in.
Example logs:

BQI> orm ir.attachment
BQI ir.attachment> debug object on
BQI ir.attachment> do search([])
[...] DEBUG:http:MultiHttpHandler init for ('127.0.0.1', 34760)
[...] DEBUG:orm:Generate order from create_date desc and None
[...] DEBUG:db.cursor:Q: SELECT "ir_attachment".id FROM "ir_attachment" ORDER BY create_date desc
[...] DEBUG:orm:ir.attachment.read([5, 4], fields=['id', 'res_model'])
[...] DEBUG:orm:ir.attachment.read_flat: tables=['"ir_attachment"'], fields_pre=['res_model']
Command 'execute' returned from server
[...] DEBUG:db.cursor:Q: SELECT id,"res_model" FROM "ir_attachment" WHERE id = ANY(ARRAY[5, 4])ORDER BY create_date desc
[...] DEBUG:db.cursor:Q: SELECT id,"res_model" FROM "ir_attachment" WHERE id = ANY(ARRAY[5, 4])ORDER BY create_date desc
Res: [5, 4]


----
[1] There is a custom Bash script to explicitly set debugging of a model in server/tools/set-obj_debug.sh . Feel free to call this method through any RPC client
[2] The BQI script is also adapted to easily set debug of orm models, see its interactive commands.

No comments:

Post a Comment